a=sendonly
13:05:03.876[app:dbg]sip: get_support_params: profile 0 supported: 'timer, 100rel, replaces'
13:05:03.876[app:dbg]Set attribute sendonly
13:05:03.876[sip]nua: nua_invite: entering
13:05:03.876[sip]nua(0x32bd00): sent signal r_invite
13:05:03.876[sip]nua(0x32bd00): recv signal r_invite
13:05:03.876[sip]nua: nua_stack_set_params: entering
13:05:03.876[sip]soa_set_params(static::0x32c100, ...) called
13:05:03.876[sip]soa_set_user_sdp(static::0x32c100, (nil), 0x31827c, -1) called
13:05:03.876[sip]soa_base_set_params: NOT reduce media: soa_session(:0x32c100, ...) called
13:05:03.876[sip]soa_init_offer_answer(static::0x32c100) called
13:05:03.876[sip]soa_generate_offer(static::0x32c100, 0) called
13:05:03.876[sip]soa_static_offer_answer_action(0x32c100, soa_generate_offer): called
13:05:03.876[sip]soa_static(0x32c100, soa_generate_offer): upgrade with local description
13:05:03.876[sip]soa_sdp_upgrade: NOT reduce media: soa_session(:0x32c100, ...) called
13:05:03.876[sip]soa_sdp_mode_set(0xbd5ffac8, (nil), ""): called
13:05:03.876[sip]soa_static(0x32c100, soa_generate_offer): storing local description
13:05:03.876[sip]soa_get_local_sdp(static::0x32c100, [(nil)], [0xbd5ffbbc], [0xbd5ffbb8]) called
13:05:03.896[sip]nta: selecting scheme sip
13:05:03.896[sip]tport_tsend(0x255000) tpn = */91.215.252.131:5060
13:05:03.896[sip]tport_resolve addrinfo = 91.215.252.131:5060
13:05:03.896[sip]tport_by_addrinfo(0x255000): not found by name */91.215.252.131:5060
13:05:03.896[sip]tport_vsend(0x255000): 948 bytes of 948 to udp/91.215.252.131:5060
13:05:03.896[sip]tport_vsend returned 948
13:05:03.896[sip]send 948 bytes to udp/[91.215.252.131]:5060 at 02:09:59.310000:
13:05:03.896[sip]   ------------------------------------------------------------------------
13:05:03.896[sip]   INVITE sip:3465265@91.215.252.131:5060 SIP/2.0
13:05:03.896[sip]   Via: SIP/2.0/UDP 10.10.10.37;rport;branch=z9hG4bKa1H6S5K795rrH
13:05:03.896[sip]   Max-Forwards: 70
13:05:03.896[sip]   From: <sip:7001@10.10.10.37:5060>;tag=j52Hp2ym5QmZg
13:05:03.896[sip]   To: <sip:3465265@10.10.10.245>;tag=1135724852
13:05:03.896[sip]   Call-ID: 1742192132@10.10.10.245
13:05:03.896[sip]   CSeq: 3899 INVITE
13:05:03.896[sip]   Contact: <sip:7001@10.10.10.37:5060>
13:05:03.896[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33024470 sofia-sip/1.12.10
13:05:03.896[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
13:05:03.896[sip]   Supported: timer, 100rel, replaces
13:05:03.896[sip]   Session-Expires: 1800
13:05:03.896[sip]   Min-SE: 120
13:05:03.896[sip]   Content-Type: application/sdp
13:05:03.896[sip]   Content-Disposition: session
13:05:03.896[sip]   Content-Length: 313
13:05:03.896[sip]
13:05:03.896[sip]   v=0
13:05:03.896[sip]   o=- 5512329718226959272 4444897156707502677 IN IP4 10.10.10.37
13:05:03.896[sip]   s=Session SDP
13:05:03.896[sip]   c=IN IP4 10.10.10.37
13:05:03.896[sip]   t=0 0
13:05:03.896[sip]   m=audio 23072 RTP/AVP 8 18 101
13:05:03.896[sip]   a=rtpmap:8 PCMA/8000
13:05:03.896[sip]   a=rtpmap:18 G729/8000
13:05:03.896[sip]   a=fmtp:18 annexb=no
13:05:03.896[sip]   a=rtpmap:101 telephone-event/8000
13:05:03.896[sip]   a=fmtp:101 0-15
13:05:03.896[sip]   a=sendonly
13:05:03.896[sip]   a=ptime:20
13:05:03.896[sip]   a=silenceSupp:on - - - -
13:05:03.896[sip]   ------------------------------------------------------------------------
13:05:03.896[sip]nta: sent INVITE (3899) to */91.215.252.131:5060
13:05:03.896[sip]tport_pend(0x255000): pending 0x31ac00 for udp/10.10.10.37:5060 (already 0)
13:05:03.896[sip]nta: timer shortened to 500 ms
13:05:03.896[sip]nua(0x32bd00): ready call updated: calling sent offer
13:05:03.896[sip]soa_get_local_sdp(static::0x32c100, [0xbd5ffbb0], [0xbd5ffbac], [(nil)]) called
13:05:03.896[sip]nua(0x32bd00): event i_state INVITE sent
13:05:03.896[sip]nua: nua_application_event: entering
13:05:03.896[app:dbg]got nua_i_state : 0(INVITE sent)
13:05:03.896[app:dbg]NO SIP IN nua_i_state == 0 : INVITE sent
13:05:03.896[app:dbg]self_i_state(): call state 2: os : local sdp : sdp_init have_oc
13:05:03.896[app:dbg]sip: call 02060005: SDP offer sent
13:05:03.896[app:dbg]self_create_local_media() 0: add rtpmap 8
13:05:03.896[app:dbg]self_create_local_media() 1: add rtpmap 18
13:05:03.896[app:dbg]self_create_local_media() 2: add rtpmap 101
13:05:03.896[app:dbg]sip: call 02060005: media stream 0, creating proposed audio channel, local RTP 10.10.10.37:23072, rtpmaps cnt: 3
13:05:03.896[app:dbg]sip: call 02060005: local SDP offer copy
13:05:03.906[sip]tport_wakeup_pri(0x255000): events IN
13:05:03.906[sip]tport_recv_event(0x255000)
13:05:03.906[sip]tport_recv_iovec(0x255000) msg 0x31e400 from (udp/10.10.10.37:5060) has 306 bytes, veclen = 1
13:05:03.906[sip]recv 306 bytes from udp/[91.215.252.131]:5060 at 02:09:59.320000:
13:05:03.906[sip]   ------------------------------------------------------------------------
13:05:03.906[sip]   SIP/2.0 100 Trying
13:05:03.906[sip]   Via: SIP/2.0/UDP 10.10.10.37:5060;rport=5060;branch=z9hG4bKa1H6S5K795rrH;received=10.10.10.37
13:05:03.906[sip]   From: <sip:7001@10.10.10.37:5060>;tag=j52Hp2ym5QmZg
13:05:03.906[sip]   To: <sip:3465265@10.10.10.245>;tag=1135724852
13:05:03.906[sip]   Call-ID: 1742192132@10.10.10.245
13:05:03.906[sip]   CSeq: 3899 INVITE
13:05:03.906[sip]   Server: ATC.PRO
13:05:03.906[sip]   Content-Length: 0
13:05:03.906[sip]
13:05:03.906[sip]   ------------------------------------------------------------------------
13:05:03.906[sip]tport_deliver(0x255000): msg 0x31e400 (306 bytes) from udp/91.215.252.131:5060/sip next=(nil)
13:05:03.906[sip]nta: received 100 Trying for INVITE (3899)
13:05:03.906[sip]nta: 100 Trying is going to a transaction
13:05:03.906[sip]nta_outgoing: RTT is 10 ms
13:05:03.906[sip]tport_release(0x255000): 0x31ac00 by 0x329900 with 0x31e400 (preliminary)
13:05:03.906[sip]nua(0x32bd00): event r_invite 100 Trying
13:05:03.906[sip]tport_wakeup_pri(0x255000): events IN
13:05:03.906[sip]tport_recv_event(0x255000)
13:05:03.906[sip]tport_recv_iovec(0x255000) msg 0x253800 from (udp/10.10.10.37:5060) has 640 bytes, veclen = 1
13:05:03.906[sip]recv 640 bytes from udp/[91.215.252.131]:5060 at 02:09:59.320000:
13:05:03.906[sip]   ------------------------------------------------------------------------
13:05:03.906[sip]   SIP/2.0 200 OK
13:05:03.906[sip]   Via: SIP/2.0/UDP 10.10.10.37:5060;rport=5060;branch=z9hG4bKa1H6S5K795rrH;received=10.10.10.37
13:05:03.906[sip]   From: <sip:7001@10.10.10.37:5060>;tag=j52Hp2ym5QmZg
13:05:03.906[sip]   To: <sip:3465265@10.10.10.245>;tag=1135724852
13:05:03.906[sip]   Call-ID: 1742192132@10.10.10.245
13:05:03.906[sip]   CSeq: 3899 INVITE
13:05:03.906[sip]   Server: ATC.PRO
13:05:03.906[sip]   Contact: <sip:3465265@91.215.252.131:5060>
13:05:03.906[sip]   Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO, MESSAGE
13:05:03.906[sip]   Content-Type: application/sdp
13:05:03.906[sip]   Content-Length: 187
13:05:03.906[sip]
13:05:03.906[sip]   v=0
13:05:03.906[sip]   o=yate 1455876300 1455876301 IN IP4 91.215.252.131
13:05:03.906[sip]   s=SIP Call
13:05:03.906[sip]   c=IN IP4 91.215.252.131
13:05:03.916[sip]nua: nua_application_event: entering
13:05:03.916[app:dbg]got nua_r_invite : 100(Trying)
13:05:03.916[app:dbg]sip: call 02060005: INVITE: 100 Trying
13:05:03.916[app:dbg]call 33947653 got 100/Trying - set received_1xx
13:05:03.916[app:dbg]Port 6: user port 0, old state holding, new state
13:05:03.916[app:dbg]Set port 6 led to state 'LED_ON'
13:05:03.916[app:dbg]pbx -[msg_fxs_state]-> group
13:05:03.926[app:dbg]ITC: [msg_fxs_state] -> group
13:05:03.926[app:dbg]-----[GM] self_fxs_state()
13:05:03.926[app:dbg]Port 6: new state is holding
13:05:03.906[sip]   t=0 0
13:05:03.926[sip]   m=audio 24458 RTP/AVP 8 101
13:05:03.926[sip]   a=rtpmap:8 PCMA/8000
13:05:03.926[sip]   a=rtpmap:101 telephone-event/8000
13:05:03.926[sip]   ------------------------------------------------------------------------
13:05:03.926[sip]tport_deliver(0x255000): msg 0x253800 (640 bytes) from udp/91.215.252.131:5060/sip next=(nil)
13:05:03.926[sip]nta: received 200 OK for INVITE (3899)
13:05:03.926[sip]nta: 200 OK is going to a transaction
13:05:03.926[sip]tport_release(0x255000): 0x31ac00 by 0x329900 with 0x253800
13:05:03.926[sip]nua(): refresh session after 905 seconds (in [895..905])
13:05:03.926[sip]nua(): refresh session after 905 seconds
13:05:03.926[sip]soa_set_remote_sdp(static::0x32c100, (nil), 0x3131c5, 187) called
13:05:03.926[sip]soa_process_answer(static::0x32c100) called
13:05:03.926[sip]soa_static_offer_answer_action(0x32c100, soa_process_answer): called
13:05:03.926[sip]soa_sdp_mode_set(0x254200, 0x33c200, ""): called
13:05:03.926[sip]soa_static(0x32c100, soa_process_answer): upgrade codecs with remote description
13:05:03.926[sip]soa_static(0x32c100, soa_process_answer): storing local description
13:05:03.926[sip]soa_activate(static::0x32c100, (nil)) called
13:05:03.926[sip]nua(0x32bd00): INVITE: processed SDP answer in 200 OK
13:05:03.926[sip]nua(0x32bd00): event r_invite 200 OK
13:05:03.926[sip]nua: nua_application_event: entering
13:05:03.926[app:dbg]got nua_r_invite : 200(OK)
13:05:03.926[app:dbg]sip: call 02060005: INVITE: 200 OK
13:05:03.926[app:dbg]Contact/Record-route on answer to INVITE: sip:3465265@91.215.252.131:5060
13:05:03.926[app:dbg]Setup new proxy addr for call; sip:3465265@91.215.252.131:5060
13:05:03.926[sip]nua: nua_set_hparams: entering
13:05:03.926[sip]nua(0x32bd00): sent signal r_set_params
13:05:03.926[sip]nua: nua_set_hparams: entering
13:05:03.926[sip]nua(0x32bd00): sent signal r_set_params
13:05:03.926[app:dbg]sip: call 02060005: current status (200)
13:05:03.926[sip]nta: selecting scheme sip
13:05:03.926[sip]tport_tsend(0x255000) tpn = */91.215.252.131:5060
13:05:03.926[sip]tport_resolve addrinfo = 91.215.252.131:5060
13:05:03.926[sip]tport_by_addrinfo(0x255000): not found by name */91.215.252.131:5060
13:05:03.926[sip]tport_vsend(0x255000): 298 bytes of 298 to udp/91.215.252.131:5060
13:05:03.946[sip]tport_vsend returned 298
13:05:03.946[sip]send 298 bytes to udp/[91.215.252.131]:5060 at 02:09:59.340000:
13:05:03.946[sip]   ------------------------------------------------------------------------
13:05:03.946[sip]   ACK sip:3465265@91.215.252.131:5060 SIP/2.0
13:05:03.946[sip]   Via: SIP/2.0/UDP 10.10.10.37;rport;branch=z9hG4bKBaBZU04a7eFBD
13:05:03.946[sip]   Max-Forwards: 70
13:05:03.946[sip]   From: <sip:7001@10.10.10.37:5060>;tag=j52Hp2ym5QmZg
13:05:03.946[sip]   To: <sip:3465265@10.10.10.245>;tag=1135724852
13:05:03.946[sip]   Call-ID: 1742192132@10.10.10.245
13:05:03.946[sip]   CSeq: 3899 ACK
13:05:03.946[sip]   Content-Length: 0
13:05:03.946[sip]
13:05:03.946[sip]   ------------------------------------------------------------------------
13:05:03.946[sip]nta: sent ACK (3899) to */91.215.252.131:5060
13:05:03.946[sip]nua(0x32bd00): ready call updated: ready received answer
13:05:03.946[sip]soa_get_remote_sdp(static::0x32c100, [0xbd5ff804], [0xbd5ff800], [(nil)]) called
13:05:03.946[sip]soa_get_params(static::0x32c100, ...) called
13:05:03.946[sip]soa_base_get_params: NOT reduce media: soa_session(:0x32c100, ...) called
13:05:03.946[sip]nua(0x32bd00): event i_state 200 OK
13:05:03.946[sip]nua: nua_application_event: entering
13:05:03.946[app:dbg]got nua_i_state : 200(OK)
13:05:03.946[app:dbg]NO SIP IN nua_i_state == 200 : OK
13:05:03.946[app:dbg]self_i_state(): call state 8: ar : remote sdp : sdp_sent have_oc
13:05:03.946[app:dbg]sip: call 02060005: SDP answer received
13:05:03.946[app:dbg]sip: call 02060005: calltype 2, mode_codec 0, codec 1
13:05:03.946[app:dbg]sip: call 02060005: SDP answer received <put on hold! (reconfig)>
13:05:03.946[app:dbg]sip: call 02060005: destroying channel of media stream 0
13:05:03.946[app:dbg]call 0x02060005 (ep 6) :: TX stop, RX stop, <reconfigure> (self_destroy_current_media)
13:05:03.946[app:dbg]sip -[msg_set_media]-> pbx
13:05:03.946[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
13:05:03.946[app:dbg]sdp_codecs_set_rfc2833() wrong param fmtp, set fmtp default '0-15'
13:05:03.946[app:dbg]sdp_codecs_set_rfc2833() present pt 101 remote fmtp 0-15, local fmtp 0-15
13:05:03.946[app:dbg]self_start_media: 1. handle call id 0x02060005, call id 0x02060005
13:05:03.946[app:dbg]change SDP mode: current mode: sendrecv, new mode: recvonly
13:05:03.946[app:dbg]sip: set options: call 02060005: media stream 0: 10.10.10.37:23072 -> 91.215.252.131:24458: MFPT 0 <reconfigure>
13:05:03.946[app:dbg]self_itc_codec(): payload 8
13:05:03.946[app:dbg]sip_set_rxtx_opts(): check rtpm <PCMA>:8
13:05:03.946[app:dbg]sip_set_rxtx_opts(): check offered 0: 8
13:05:03.946[app:dbg]self_itc_codec(): payload 8
13:05:03.946[app:dbg]Supported codec[0]: <G.711A>:8, vbd off, vad on, ecan on
13:05:03.946[app:dbg]validate_ptime() codec G.711A, ptime 20, check_bigger 1, present 1
13:05:03.946[app:dbg]validate_ptime() using 20
13:05:03.946[app:dbg]sdp_codecs_set_ptime() ptime present : 20
13:05:03.946[app:dbg]sip_set_rxtx_opts(): check rtpm <telephone-event>:101
13:05:03.946[app:dbg]sip_set_rxtx_opts(): check offered 0: 8
13:05:03.946[app:dbg]sip_set_rxtx_opts(): check offered 1: 18
13:05:03.946[app:dbg]sip_set_rxtx_opts(): check offered 2: 101
13:05:03.946[app:dbg]self_itc_codec(): payload 101
13:05:03.946[app:dbg]validate_ptime() codec G.711A, ptime 20, check_bigger 1, present 1
13:05:03.946[app:dbg]validate_ptime() using 20
13:05:03.946[app:dbg]sdp_codecs_set_ptime() ptime present : 20
13:05:03.946[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
13:05:03.946[app:dbg]validate_ptime() codec G.711A, ptime 20, check_bigger 1, present 1
13:05:03.946[app:dbg]validate_ptime() using 20
13:05:03.946[app:dbg]sdp_codecs_set_ptime() ptime present : 20
13:05:03.946[app:dbg]self_start_media: 2. handle call id 0x02060005, call id 0x02060005
13:05:03.946[app:dbg]sip -[msg_set_media]-> pbx
13:05:03.946[app:dbg]sip: call 02060005: ACK from sip:7001@10.10.10.37:5060
13:05:03.946[app:dbg]sip: call 02060005: ACK from sip:7001@10.10.10.37:5060
13:05:03.956[sip]nua(0x32bd00): event i_active 200 Call active
13:05:03.956[sip]nua: nua_application_event: entering
13:05:03.956[app:dbg]got nua_i_active : 200(Call active)
13:05:03.956[app:dbg]NO SIP IN nua_i_active == 200 : Call active
13:05:03.956[sip]nua(0x32bd00): recv signal r_set_params
13:05:03.956[sip]nua: nua_stack_set_params: entering
13:05:03.956[sip]soa_set_params(static::0x32c100, ...) called
13:05:03.956[sip]nua(0x32bd00): event r_set_params 200 OK
13:05:03.956[sip]nua: nua_application_event: entering
13:05:03.956[app:dbg]got nua_r_set_params : 200(OK)
13:05:03.956[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
13:05:03.956[sip]nua(0x32bd00): recv signal r_set_params
13:05:03.956[sip]nua: nua_stack_set_params: entering
13:05:03.956[sip]soa_set_params(static::0x32c100, ...) called
13:05:03.956[sip]nua(0x32bd00): event r_set_params 200 OK
13:05:03.956[sip]nua: nua_application_event: entering
13:05:03.956[app:dbg]got nua_r_set_params : 200(OK)
13:05:03.956[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
13:05:03.966[app:dbg]vapi: generic event, code 5 <SSRC change>, conn 0
13:05:03.976[app:dbg]ITC: [msg_set_media] -> pbx
13:05:03.976[app:dbg]self_on_set_media: call id 0x02060005 tx/rx 0/0
13:05:03.976[app:dbg]dump_port_calls() SLIC 6:
13:05:03.976[app:dbg]Q:NONE
13:05:03.976[app:dbg]H:(0x314000,0x02060005,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
13:05:03.976[app:dbg]SLIC 6: TX stop / RX stop
13:05:03.976[app:dbg]SLIC 6: send only 0
13:05:03.976[app:dbg]incom_calls_set_media_started() call 0x02060005, group -1, task <sip> media stopped
13:05:03.976[app:dbg]CMD_SET_VOICE: port = 6
13:05:03.976[app:dbg]Port 6: check vapi queue ('free') at vapi_start_stop_chan:1623
13:05:03.976[app:dbg]Chan 6: current state is CREATED
13:05:03.976[app:dbg]vapi: Conn 6. start_stop voice chan, TX stop, RX stop
13:05:03.976[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'set voice' at vapi_start_stop_chan:1666
13:05:03.976[app:dbg]VQ Conn 6 = MSP :     'set voice' =
13:05:03.976[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000401
13:05:03.986[app:dbg]ITC: [msg_set_media] -> pbx
13:05:03.986[app:dbg]self_on_set_media: call id 0x02060005 tx/rx 1/-1
13:05:03.986[app:dbg]dump_port_calls() SLIC 6:
13:05:03.986[app:dbg]Q:NONE
13:05:03.986[app:dbg]H:(0x314000,0x02060005,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
13:05:03.986[app:dbg]SLIC 6: switch to sendonly for holded call
13:05:03.986[app:dbg]SLIC 6: use 1st holded media for holded call
13:05:03.986[app:dbg]SLIC 6: TX start / RX stop: 10.10.10.37:23072->91.215.252.131:24458, <G.711A:8>
13:05:03.986[app:dbg]SLIC 6: send only 1 vad 1 g723_hr 1 vbd 0, ecan 1 rfc2833 pt 101, NSE pt 0, MFPT 0
13:05:03.986[app:dbg]incom_calls_set_media_started() call 0x02060005, group -1, task <sip> media started
13:05:03.986[app:dbg]self_set_media_start(): set ptime to 20
13:05:03.986[app:dbg]port_set_ip_param
13:05:03.986[app:dbg]set media param for '6', 10.10.10.37:23072, mode=local, random 82
13:05:03.986[app:dbg]port_set_ip_param
13:05:03.986[app:dbg]set media param for '6', 91.215.252.131:24458, mode=remote, random 82
13:05:03.986[app:dbg]CMD_CREATE_IPONLY_CONN: port = 6
13:05:03.986[app:dbg]Port 6: check vapi queue ('busy''set voice') at vapi_create_holded_chan:796
13:05:03.986[app:dbg]Port 6 put cmd 'create holded',cur 'set voice' to queue at (vapi_create_holded_chan:802)
13:05:03.986[app:dbg]VQ Conn 14 = MSP :     'set voice' =
13:05:03.986[app:dbg]VQ Conn 14 + 02  : 'create holded' (hold) + <-get_ptr
13:05:03.986[app:dbg]SLIC 6: starting media (G.711A) 10.10.10.37:23072 -> 91.215.252.131:24458
13:05:03.986[app:dbg]port 6: start voice - first time
13:05:03.986[app:dbg]port_start_holded_voice() chan 14: remote IP <91.215.252.131> (arp query 0 times)
13:05:03.986[app:dbg]chan 14: get mac succesfull, repeat 0 times
13:05:03.986[app:dbg]CMD_START_VOICE: port = 14
13:05:03.986[app:dbg]vapi_set_chan_param: chan=14 hold=1 deactivate=0
13:05:03.986[app:dbg]Port 6: check vapi queue ('busy''set voice') at vapi_set_chan_param:2136
13:05:03.986[app:dbg]Port 6 put cmd 'start voice',cur 'set voice' to queue at (vapi_set_chan_param:2148)
13:05:03.986[app:dbg]VQ Conn 14 = MSP :     'set voice' =
13:05:03.986[app:dbg]VQ Conn 14 + 02  : 'create holded' (hold) + <-get_ptr
13:05:03.986[app:dbg]VQ Conn 14 + 03  :   'start voice' (hold) +
13:05:03.986[app:dbg]vapi_proc_event: VAPI_CB
13:05:03.986[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000401 result 0x00000000
13:05:03.986[app:dbg]vapi: conn 6. RTCP disabled
13:05:03.986[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x000004ff
13:05:03.996[app:dbg]vapi_proc_event: VAPI_CB
13:05:03.996[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x000004ff result 0x00000000
13:05:03.996[app:dbg]Conn 6: Set voice mode successeful
13:05:03.996[app:dbg]Stop all medias on chan 6
13:05:03.996[app:dbg]Port 6: check vapi queue ('busy''set voice') at vapi_next_ops:2532
13:05:03.996[app:dbg]Port 6 get cmd 'create holded' from queue at (vapi_next_ops:2551)
13:05:03.996[app:dbg]VQ Conn 6 + 03  :   'start voice' (hold) + <-get_ptr
13:05:03.996[app:dbg]Port 6: check vapi queue ('free') at vapi_create_holded_chan:796
13:05:03.996[app:dbg]Chan 14: current state is INITIAL
13:05:03.996[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'create' at vapi_create_holded_chan:834
13:05:03.996[app:dbg]VQ Conn 14 = MSP :        'create' =
13:05:03.996[app:dbg]VQ Conn 14 + 03  :   'start voice' (hold) + <-get_ptr
13:05:03.996[app:dbg]Creating holded connection 14 on port 6(CW=0)....
13:05:03.996[app:dbg]Chan 14: INITIAL -> CREATING
13:05:03.996[app:dbg]Mute all RX-TX medias on SLIC 6
13:05:03.996[app:dbg]Mute media on chan 6[mute 1]
13:05:03.996[app:dbg]vapi_cb_req: 14 0 result 0x00000000 requid 0x0000004f
13:05:04.006[app:dbg]vapi_proc_event: VAPI_CB
13:05:04.006[app:dbg]vapi_cb_chan: chan 14 reqest_id 0x0000004f result 0x00000000
13:05:04.006[app:dbg]vapi_cb_req: 14 0 result 0x00000000 requid 0x00000000
13:05:04.016[app:dbg]vapi_proc_event: VAPI_CB
13:05:04.016[app:dbg]vapi_cb_chan: chan 14 reqest_id 0x00000000 result 0x00000000
13:05:04.016[app:dbg]vapi: Conn 14 - << CREATED >>
13:05:04.016[app:dbg]vapi: Conn 14 - fix DTMF detector
13:05:04.016[app:dbg]vapi_cb_req: 14 0 result 0x00000000 requid 0x00000049
13:05:04.026[app:dbg]vapi_proc_event: VAPI_CB
13:05:04.026[app:dbg]vapi_cb_chan: chan 14 reqest_id 0x00000049 result 0x00000000
13:05:04.026[app:dbg]vapi: Conn 14 - fix CNG generator
13:05:04.026[app:dbg]vapi_cb_req: 14 0 result 0x00000000 requid 0x0000004c
13:05:04.036[app:dbg]vapi_proc_event: VAPI_CB
13:05:04.036[app:dbg]vapi_cb_chan: chan 14 reqest_id 0x0000004c result 0x00000000
13:05:04.036[app:dbg]vapi: Conn 14 - caller id Set param
13:05:04.036[app:dbg]vapi: chan '14' set param Caller ID
13:05:04.036[app:dbg]vapi_cb_req: 14 0 result 0x00000000 requid 0x0000000c
13:05:04.046[app:dbg]vapi_proc_event: VAPI_CB
13:05:04.046[app:dbg]vapi_cb_chan: chan 14 reqest_id 0x0000000c result 0x00000000
13:05:04.046[app:dbg]vapi: Conn 14 - enable ind ptime and pt
13:05:04.046[app:dbg]vapi_cb_req: 14 0 result 0x00000000 requid 0x0000004a
13:05:04.056[app:dbg]vapi_proc_event: VAPI_CB
13:05:04.056[app:dbg]vapi_cb_chan: chan 14 reqest_id 0x0000004a result 0x00000000
13:05:04.056[app:dbg]Chan 14: CREATING -> CREATED
13:05:04.056[app:dbg]Port 6: check vapi queue ('busy''create') at vapi_next_ops:2532
13:05:04.056[app:dbg]Port 6 get cmd 'start voice' from queue at (vapi_next_ops:2551)
13:05:04.056[app:dbg]vapi_set_chan_param: chan=14 hold=1 deactivate=0
13:05:04.056[app:dbg]Port 6: check vapi queue ('free') at vapi_set_chan_param:2136
13:05:04.056[app:dbg]Chan 14: current state is CREATED
13:05:04.056[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'start voice' at vapi_set_chan_param:2160
13:05:04.056[app:dbg]VQ Conn 14 = MSP :   'start voice' =
13:05:04.056[app:dbg]Conn 22 Eth src=00:00:00:00:00:00, dst=00:00:00:00:00:00
13:05:04.056[app:dbg]Conn 22 IP src=0.0.0.0:23072, dst=91.215.252.131:24458
13:05:04.056[app:dbg]CHECK REQID: 0x00000502(Conn 14)
13:05:04.056[app:dbg]vapi: Conn 14. Disable - Ok
13:05:04.056[app:dbg]vapi_cb_req: 14 0 result 0x00000000 requid 0x00000502
13:05:04.066[app:dbg]VQ Conn 14 = MSP :   'start voice' =
13:05:04.066[app:dbg]vapi_proc_event: VAPI_CB
13:05:04.066[app:dbg]vapi_cb_chan: chan 14 reqest_id 0x00000502 result 0x00000000
13:05:04.066[app:dbg]VOIP_DISABLE: chan = 14
13:05:04.066[app:dbg]vapi_cb_setchan: chan 14 deactivate 0
13:05:04.066[app:dbg]vapi: create: TDM channel 14 Set SSRC to 215E5705
13:05:04.066[app:dbg]vapi: Conn 14. Set src/dst eth mac - Ok
13:05:04.066[app:dbg]Reserved IP: 192.168.253.1
13:05:04.066[app:dbg]vapi_cb_setchan: ch14. msp_ip = 192.168.253.2
13:05:04.066[app:dbg]IP PARAMS: 1FDA8C0 30072 2FDA8C0 30072
13:05:04.066[app:dbg]vapi: Conn 14. Set src/dst ip addr - ok
13:05:04.066[app:dbg]vapi_cb_req: 14 0 result 0xfffff4f1 requid 0x00000508
13:05:04.076[app:dbg]vapi_proc_event: VAPI_CB
13:05:04.076[app:dbg]vapi_cb_chan: chan 14 reqest_id 0x00000508 result 0xfffff4f1
13:05:04.076[app:dbg]VOIP_SET_IP: chan = 14
13:05:04.076[app:ERR]vapi: Conn 14. State 'Set Chan'. Command 8 - Error: -2831 (MSP error 0b0f)
13:05:04.076[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:04.076[app:dbg]Create RX-TX media for SLIC 14(sendonly: 1, rtcp: 0)
13:05:04.076[app:dbg]Can't bind - try to clear binding call from prev connection
13:05:04.076[app:dbg]Delete all RX-TX with RTP port = 23072
13:05:04.076[app:dbg]Clear media from SLIC 6
13:05:04.406[sip]nta: timer set next to 1480 ms
13:05:05.206[sip]nta: selecting scheme sip
13:05:05.206[sip]tport_tsend(0x255000) tpn = udp/91.215.252.131:5060/sip
13:05:05.206[sip]tport_resolve addrinfo = 91.215.252.131:5060
13:05:05.206[sip]tport_by_addrinfo(0x255000): not found by name udp/91.215.252.131:5060/sip
13:05:05.206[sip]tport_vsend(0x255000): 741 bytes of 741 to udp/91.215.252.131:5060
13:05:05.206[sip]tport_vsend returned 741
13:05:05.206[sip]send 741 bytes to udp/[91.215.252.131]:5060 at 02:10:00.620000:
13:05:05.206[sip]   ------------------------------------------------------------------------
13:05:05.206[sip]   REGISTER sip:91.215.252.131 SIP/2.0
13:05:05.206[sip]   Via: SIP/2.0/UDP 10.10.10.37;rport;branch=z9hG4bKcK4QXUNe4Q5Xr
13:05:05.206[sip]   Max-Forwards: 70
13:05:05.206[sip]   From: <sip:7006@91.215.252.131>;tag=UNXQDmU37amHp
13:05:05.206[sip]   To: <sip:7006@91.215.252.131>
13:05:05.206[sip]   Call-ID: 0bf0c88c-5181-1234-5481-a8f94b0e769a
13:05:05.206[sip]   CSeq: 231 REGISTER
13:05:05.206[sip]   Contact: <sip:7006@10.10.10.37:5060>
13:05:05.206[sip]   Expires: 120
13:05:05.206[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33024470 sofia-sip/1.12.10
13:05:05.206[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
13:05:05.206[sip]   Supported: timer, 100rel, replaces, path
13:05:05.206[sip]   Authorization: Digest username="7006", realm="sip3.line.ru", nonce="24457ac979f1ad28577e19618ecafdf7.1455876241", algorithm=MD5, uri="sip:91.215.252.131", response="1ce2507feb0effae42e5963a3dc5f02b"
13:05:05.206[sip]   Content-Length: 0
13:05:05.206[sip]
13:05:05.206[sip]   ------------------------------------------------------------------------
13:05:05.206[sip]nta: sent REGISTER (231) to udp/91.215.252.131:5060/sip
13:05:05.206[sip]tport_pend(0x255000): pending 0x31de00 for udp/10.10.10.37:5060 (already 0)
13:05:05.206[sip]nta: timer shortened to 500 ms
13:05:05.216[sip]tport_wakeup_pri(0x255000): events IN
13:05:05.216[sip]tport_recv_event(0x255000)
13:05:05.216[sip]tport_recv_iovec(0x255000) msg 0x355800 from (udp/10.10.10.37:5060) has 302 bytes, veclen = 1
13:05:05.216[sip]recv 302 bytes from udp/[91.215.252.131]:5060 at 02:10:00.630000:
13:05:05.216[sip]   ------------------------------------------------------------------------
13:05:05.216[sip]   SIP/2.0 100 Trying
13:05:05.216[sip]   Via: SIP/2.0/UDP 10.10.10.37:5060;rport=5060;branch=z9hG4bKcK4QXUNe4Q5Xr;received=10.10.10.37
13:05:05.216[sip]   From: <sip:7006@91.215.252.131>;tag=UNXQDmU37amHp
13:05:05.216[sip]   To: <sip:7006@91.215.252.131>
13:05:05.216[sip]   Call-ID: 0bf0c88c-5181-1234-5481-a8f94b0e769a
13:05:05.216[sip]   CSeq: 231 REGISTER
13:05:05.216[sip]   Server: ATC.PRO
13:05:05.216[sip]   Content-Length: 0
13:05:05.216[sip]
13:05:05.216[sip]   ------------------------------------------------------------------------
13:05:05.216[sip]tport_deliver(0x255000): msg 0x355800 (302 bytes) from udp/91.215.252.131:5060/sip next=(nil)
13:05:05.216[sip]nta: received 100 Trying for REGISTER (231)
13:05:05.216[sip]nta: 100 Trying is going to a transaction
13:05:05.216[sip]nta_outgoing: RTT is 10 ms
13:05:05.216[sip]tport_release(0x255000): 0x31de00 by 0x32a100 with 0x355800 (preliminary)
13:05:05.216[sip]nua(0x32d800): event r_register 100 Trying
13:05:05.216[sip]nua: nua_application_event: entering
13:05:05.216[app:dbg]got nua_r_register : 100(Trying)
13:05:05.216[app:dbg]sip: endpoint 3: REGISTER: 100 Trying
13:05:05.216[app:dbg]Port 3: user port 5, old state hangup, new state
13:05:05.226[app:dbg]port 3: set led 3
13:05:05.226[app:dbg]Set port 3 led to state 'LED_FAIL'
13:05:05.226[sip]tport_wakeup_pri(0x255000): events IN
13:05:05.226[sip]tport_recv_event(0x255000)
13:05:05.226[sip]tport_recv_iovec(0x255000) msg 0x31b000 from (udp/10.10.10.37:5060) has 509 bytes, veclen = 1
13:05:05.226[sip]recv 509 bytes from udp/[91.215.252.131]:5060 at 02:10:00.640000:
13:05:05.226[sip]   ------------------------------------------------------------------------
13:05:05.226[sip]   SIP/2.0 401 Unauthorized
13:05:05.226[sip]   Via: SIP/2.0/UDP 10.10.10.37:5060;rport=5060;branch=z9hG4bKcK4QXUNe4Q5Xr;received=10.10.10.37
13:05:05.226[sip]   From: <sip:7006@91.215.252.131>;tag=UNXQDmU37amHp
13:05:05.226[sip]   To: <sip:7006@91.215.252.131>
13:05:05.226[sip]   Call-ID: 0bf0c88c-5181-1234-5481-a8f94b0e769a
13:05:05.226[sip]   CSeq: 231 REGISTER
13:05:05.226[sip]   WWW-Authenticate: Digest realm="sip3.line.ru", nonce="9c6f5e0812159c63c35afe3d3d1bb363.1455876306", stale=TRUE, algorithm=MD5
13:05:05.226[sip]   Server: ATC.PRO
13:05:05.236[sip]   Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO, MESSAGE
13:05:05.236[sip]   Content-Length: 0
13:05:05.236[sip]
13:05:05.236[sip]   ------------------------------------------------------------------------
13:05:05.236[sip]tport_deliver(0x255000): msg 0x31b000 (509 bytes) from udp/91.215.252.131:5060/sip next=(nil)
13:05:05.236[sip]nta: received 401 Unauthorized for REGISTER (231)
13:05:05.236[sip]nta: 401 Unauthorized is going to a transaction
13:05:05.236[sip]tport_release(0x255000): 0x31de00 by 0x32a100 with 0x31b000
13:05:05.236[sip]auth_digest_challenge_get(): got 5
13:05:05.236[sip]nta: selecting scheme sip
13:05:05.236[sip]tport_tsend(0x255000) tpn = udp/91.215.252.131:5060/sip
13:05:05.236[sip]tport_resolve addrinfo = 91.215.252.131:5060
13:05:05.236[sip]tport_by_addrinfo(0x255000): not found by name udp/91.215.252.131:5060/sip
13:05:05.236[sip]tport_vsend(0x255000): 741 bytes of 741 to udp/91.215.252.131:5060
13:05:05.236[sip]tport_vsend returned 741
13:05:05.236[sip]send 741 bytes to udp/[91.215.252.131]:5060 at 02:10:00.650000:
13:05:05.236[sip]   ------------------------------------------------------------------------
13:05:05.236[sip]   REGISTER sip:91.215.252.131 SIP/2.0
13:05:05.236[sip]   Via: SIP/2.0/UDP 10.10.10.37;rport;branch=z9hG4bKDvXgZp6H10Ugm
13:05:05.236[sip]   Max-Forwards: 70
13:05:05.236[sip]   From: <sip:7006@91.215.252.131>;tag=UNXQDmU37amHp
13:05:05.236[sip]   To: <sip:7006@91.215.252.131>
13:05:05.236[sip]   Call-ID: 0bf0c88c-5181-1234-5481-a8f94b0e769a
13:05:05.236[sip]   CSeq: 232 REGISTER
13:05:05.236[sip]   Contact: <sip:7006@10.10.10.37:5060>
13:05:05.236[sip]   Expires: 120
13:05:05.236[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33024470 sofia-sip/1.12.10
13:05:05.236[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
13:05:05.236[sip]   Supported: timer, 100rel, replaces, path
13:05:05.236[sip]   Authorization: Digest username="7006", realm="sip3.line.ru", nonce="9c6f5e0812159c63c35afe3d3d1bb363.1455876306", algorithm=MD5, uri="sip:91.215.252.131", response="2958af8660dc6e1f01ffaf8c586a4a01"
13:05:05.236[sip]   Content-Length: 0
13:05:05.236[sip]
13:05:05.236[sip]   ------------------------------------------------------------------------
13:05:05.236[sip]nta: sent REGISTER (232) to udp/91.215.252.131:5060/sip
13:05:05.236[sip]tport_pend(0x255000): pending 0x31cc00 for udp/10.10.10.37:5060 (already 0)
13:05:05.236[sip]nua(0x32d800): event r_register 100 Request Authorized by Cache
13:05:05.236[sip]nua: nua_application_event: entering
13:05:05.236[app:dbg]got nua_r_register : 100(Request Authorized by Cache)
13:05:05.236[app:dbg]sip: endpoint 3: REGISTER: 100 Request Authorized by Cache
13:05:05.236[app:dbg]Port 3: user port 5, old state hangup, new state
13:05:05.246[sip]tport_wakeup_pri(0x255000): events IN
13:05:05.246[sip]tport_recv_event(0x255000)
13:05:05.246[sip]tport_recv_iovec(0x255000) msg 0x355800 from (udp/10.10.10.37:5060) has 302 bytes, veclen = 1
13:05:05.246[sip]recv 302 bytes from udp/[91.215.252.131]:5060 at 02:10:00.660000:
13:05:05.246[sip]   ------------------------------------------------------------------------
13:05:05.246[sip]   SIP/2.0 100 Trying
13:05:05.246[sip]   Via: SIP/2.0/UDP 10.10.10.37:5060;rport=5060;branch=z9hG4bKDvXgZp6H10Ugm;received=10.10.10.37
13:05:05.246[sip]   From: <sip:7006@91.215.252.131>;tag=UNXQDmU37amHp
13:05:05.246[sip]   To: <sip:7006@91.215.252.131>
13:05:05.246[sip]   Call-ID: 0bf0c88c-5181-1234-5481-a8f94b0e769a
13:05:05.246[sip]   CSeq: 232 REGISTER
13:05:05.246[sip]   Server: ATC.PRO
13:05:05.246[sip]   Content-Length: 0
13:05:05.246[sip]
13:05:05.246[sip]   ------------------------------------------------------------------------
13:05:05.246[sip]tport_deliver(0x255000): msg 0x355800 (302 bytes) from udp/91.215.252.131:5060/sip next=(nil)
13:05:05.246[sip]nta: received 100 Trying for REGISTER (232)
13:05:05.246[sip]nta: 100 Trying is going to a transaction
13:05:05.246[sip]nta_outgoing: RTT is 10 ms
13:05:05.246[sip]tport_release(0x255000): 0x31cc00 by 0x2f8800 with 0x355800 (preliminary)
13:05:05.246[sip]nua(0x32d800): event r_register 100 Trying
13:05:05.256[sip]nua: nua_application_event: entering
13:05:05.256[app:dbg]got nua_r_register : 100(Trying)
13:05:05.256[app:dbg]sip: endpoint 3: REGISTER: 100 Trying
13:05:05.256[app:dbg]Port 3: user port 5, old state hangup, new state
13:05:05.356[sip]tport_wakeup_pri(0x255000): events IN
13:05:05.356[sip]tport_recv_event(0x255000)
13:05:05.356[sip]tport_recv_iovec(0x255000) msg 0x33f400 from (udp/10.10.10.37:5060) has 451 bytes, veclen = 1
13:05:05.366[sip]recv 451 bytes from udp/[91.215.252.131]:5060 at 02:10:00.770000:
13:05:05.366[sip]   ------------------------------------------------------------------------
13:05:05.366[sip]   SIP/2.0 200 OK
13:05:05.366[sip]   Via: SIP/2.0/UDP 10.10.10.37:5060;rport=5060;branch=z9hG4bKDvXgZp6H10Ugm;received=10.10.10.37
13:05:05.366[sip]   From: <sip:7006@91.215.252.131>;tag=UNXQDmU37amHp
13:05:05.366[sip]   To: <sip:7006@91.215.252.131>;tag=1331197889
13:05:05.366[sip]   Call-ID: 0bf0c88c-5181-1234-5481-a8f94b0e769a
13:05:05.366[sip]   CSeq: 232 REGISTER
13:05:05.366[sip]   Expires: 120
13:05:05.366[sip]   Contact: <sip:7006@10.10.10.37:5060>;expires=120
13:05:05.366[sip]   Server: ATC.PRO
13:05:05.366[sip]   Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO, MESSAGE
13:05:05.366[sip]   Content-Length: 0
13:05:05.366[sip]
13:05:05.366[sip]   ------------------------------------------------------------------------
13:05:05.366[sip]tport_deliver(0x255000): msg 0x33f400 (451 bytes) from udp/91.215.252.131:5060/sip next=(nil)
13:05:05.366[sip]nta: received 200 OK for REGISTER (232)
13:05:05.366[sip]nta: 200 OK is going to a transaction
13:05:05.366[sip]tport_release(0x255000): 0x31cc00 by 0x2f8800 with 0x33f400
13:05:05.366[sip]nua(): refresh register after 80 seconds (in [60..90])
13:05:05.366[sip]nua(): refresh register after 80 seconds
13:05:05.366[sip]nua(0x32d800): event r_register 200 OK
13:05:05.366[sip]nua: nua_application_event: entering
13:05:05.366[app:dbg]got nua_r_register : 200(OK)
13:05:05.366[app:dbg]sip: endpoint 3: REGISTER: 200 OK
13:05:05.366[app:dbg]Port 3: user port 5, old state hangup, new state
13:05:05.366[app:dbg]sip: endpoint 3: successfully registered
13:05:05.376[app:dbg]port 3: set led 1
13:05:05.376[app:dbg]Set port 3 led to state 'LED_OFF'
13:05:05.716[sip]nta: timer set next to 170 ms
13:05:05.896[sip]nta: timer I fired, terminate 200 response
13:05:05.896[sip]incoming_reclaim_all((nil), (nil), 0xbd5ffcc4)
13:05:05.896[sip]nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free
13:05:05.896[sip]nta: timer set next to 4330 ms
13:05:10.236[sip]nta: timer K fired, terminate REGISTER (231)
13:05:10.236[sip]outgoing_reclaim_all((nil), (nil), 0xbd5ffcc4)
13:05:10.236[sip]nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/3 term, 1/4 free
13:05:10.236[sip]nta: timer set next to 120 ms
13:05:10.366[sip]nta: timer K fired, terminate REGISTER (232)
13:05:10.366[sip]outgoing_reclaim_all((nil), (nil), 0xbd5ffcc4)
13:05:10.366[sip]nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free
13:05:10.366[sip]nta: timer set next to 25540 ms
13:05:14.296[sip]nta: selecting scheme sip
13:05:14.296[sip]tport_tsend(0x255000) tpn = udp/91.215.252.131:5060/sip
13:05:14.296[sip]tport_resolve addrinfo = 91.215.252.131:5060
13:05:14.296[sip]tport_by_addrinfo(0x255000): not found by name udp/91.215.252.131:5060/sip
13:05:14.296[sip]tport_vsend(0x255000): 741 bytes of 741 to udp/91.215.252.131:5060
13:05:14.296[sip]tport_vsend returned 741
13:05:14.296[sip]send 741 bytes to udp/[91.215.252.131]:5060 at 02:10:09.710000:
13:05:14.296[sip]   ------------------------------------------------------------------------
13:05:14.296[sip]   REGISTER sip:91.215.252.131 SIP/2.0
13:05:14.296[sip]   Via: SIP/2.0/UDP 10.10.10.37;rport;branch=z9hG4bKe5p90HQNy9H3F
13:05:14.296[sip]   Max-Forwards: 70
13:05:14.296[sip]   From: <sip:7004@91.215.252.131>;tag=X7F9gaXa2v0pD
13:05:14.296[sip]   To: <sip:7004@91.215.252.131>
13:05:14.296[sip]   Call-ID: 0c8ae5ac-5181-1234-5681-a8f94b0e769a
13:05:14.296[sip]   CSeq: 230 REGISTER
13:05:14.296[sip]   Contact: <sip:7004@10.10.10.37:5060>
13:05:14.296[sip]   Expires: 120
13:05:14.296[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33024470 sofia-sip/1.12.10
13:05:14.296[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
13:05:14.296[sip]   Supported: timer, 100rel, replaces, path
13:05:14.296[sip]   Authorization: Digest username="7004", realm="sip3.line.ru", nonce="8f77e75b1b36d7fd5805edf213c20aac.1455876250", algorithm=MD5, uri="sip:91.215.252.131", response="da0baf08b9d62fad9dd5db313ef5a099"
13:05:14.296[sip]   Content-Length: 0
13:05:14.296[sip]
13:05:14.296[sip]   ------------------------------------------------------------------------
13:05:14.296[sip]nta: sent REGISTER (230) to udp/91.215.252.131:5060/sip
13:05:14.296[sip]tport_pend(0x255000): pending 0x31d000 for udp/10.10.10.37:5060 (already 0)
13:05:14.296[sip]nta: timer shortened to 500 ms
13:05:14.306[sip]tport_wakeup_pri(0x255000): events IN
13:05:14.306[sip]tport_recv_event(0x255000)
13:05:14.306[sip]tport_recv_iovec(0x255000) msg 0x339400 from (udp/10.10.10.37:5060) has 302 bytes, veclen = 1
13:05:14.306[sip]recv 302 bytes from udp/[91.215.252.131]:5060 at 02:10:09.720000:
13:05:14.306[sip]   ------------------------------------------------------------------------
13:05:14.306[sip]   SIP/2.0 100 Trying
13:05:14.306[sip]   Via: SIP/2.0/UDP 10.10.10.37:5060;rport=5060;branch=z9hG4bKe5p90HQNy9H3F;received=10.10.10.37
13:05:14.306[sip]   From: <sip:7004@91.215.252.131>;tag=X7F9gaXa2v0pD
13:05:14.306[sip]   To: <sip:7004@91.215.252.131>
13:05:14.306[sip]   Call-ID: 0c8ae5ac-5181-1234-5681-a8f94b0e769a
13:05:14.306[sip]   CSeq: 230 REGISTER
13:05:14.306[sip]   Server: ATC.PRO
13:05:14.306[sip]   Content-Length: 0
13:05:14.306[sip]
13:05:14.306[sip]   ------------------------------------------------------------------------
13:05:14.306[sip]tport_deliver(0x255000): msg 0x339400 (302 bytes) from udp/91.215.252.131:5060/sip next=(nil)
13:05:14.306[sip]nta: received 100 Trying for REGISTER (230)
13:05:14.306[sip]nta: 100 Trying is going to a transaction
13:05:14.306[sip]nta_outgoing: RTT is 10 ms
13:05:14.306[sip]tport_release(0x255000): 0x31d000 by 0x2f8800 with 0x339400 (preliminary)
13:05:14.306[sip]nua(0x32d400): event r_register 100 Trying
13:05:14.306[sip]nua: nua_application_event: entering
13:05:14.306[app:dbg]got nua_r_register : 100(Trying)
13:05:14.306[app:dbg]sip: endpoint 5: REGISTER: 100 Trying
13:05:14.306[app:dbg]Port 5: user port 3, old state hangup, new state
13:05:14.336[app:dbg]port 5: set led 3
13:05:14.336[app:dbg]Set port 5 led to state 'LED_FAIL'
13:05:14.356[sip]tport_wakeup_pri(0x255000): events IN
13:05:14.356[sip]tport_recv_event(0x255000)
13:05:14.356[sip]tport_recv_iovec(0x255000) msg 0x33f400 from (udp/10.10.10.37:5060) has 509 bytes, veclen = 1
13:05:14.356[sip]recv 509 bytes from udp/[91.215.252.131]:5060 at 02:10:09.770000:
13:05:14.356[sip]   ------------------------------------------------------------------------
13:05:14.356[sip]   SIP/2.0 401 Unauthorized
13:05:14.356[sip]   Via: SIP/2.0/UDP 10.10.10.37:5060;rport=5060;branch=z9hG4bKe5p90HQNy9H3F;received=10.10.10.37
13:05:14.356[sip]   From: <sip:7004@91.215.252.131>;tag=X7F9gaXa2v0pD
13:05:14.356[sip]   To: <sip:7004@91.215.252.131>
13:05:14.356[sip]   Call-ID: 0c8ae5ac-5181-1234-5681-a8f94b0e769a
13:05:14.356[sip]   CSeq: 230 REGISTER
13:05:14.356[sip]   WWW-Authenticate: Digest realm="sip3.line.ru", nonce="4861237c63c12b6b058abee55a42cc0b.1455876315", stale=TRUE, algorithm=MD5
13:05:14.356[sip]   Server: ATC.PRO
13:05:14.356[sip]   Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO, MESSAGE
13:05:14.356[sip]   Content-Length: 0
13:05:14.356[sip]
13:05:14.356[sip]   ------------------------------------------------------------------------
13:05:14.356[sip]tport_deliver(0x255000): msg 0x33f400 (509 bytes) from udp/91.215.252.131:5060/sip next=(nil)
13:05:14.356[sip]nta: received 401 Unauthorized for REGISTER (230)
13:05:14.356[sip]nta: 401 Unauthorized is going to a transaction
13:05:14.356[sip]tport_release(0x255000): 0x31d000 by 0x2f8800 with 0x33f400
13:05:14.356[sip]auth_digest_challenge_get(): got 5
13:05:14.366[sip]nta: selecting scheme sip
13:05:14.366[sip]tport_tsend(0x255000) tpn = udp/91.215.252.131:5060/sip
13:05:14.366[sip]tport_resolve addrinfo = 91.215.252.131:5060
13:05:14.366[sip]tport_by_addrinfo(0x255000): not found by name udp/91.215.252.131:5060/sip
13:05:14.366[sip]tport_vsend(0x255000): 741 bytes of 741 to udp/91.215.252.131:5060
13:05:14.366[sip]tport_vsend returned 741
13:05:14.366[sip]send 741 bytes to udp/[91.215.252.131]:5060 at 02:10:09.780000:
13:05:14.366[sip]   ------------------------------------------------------------------------
13:05:14.366[sip]   REGISTER sip:91.215.252.131 SIP/2.0
13:05:14.366[sip]   Via: SIP/2.0/UDP 10.10.10.37;rport;branch=z9hG4bKFeg22c8rUj8NB
13:05:14.366[sip]   Max-Forwards: 70
13:05:14.366[sip]   From: <sip:7004@91.215.252.131>;tag=X7F9gaXa2v0pD
13:05:14.366[sip]   To: <sip:7004@91.215.252.131>
13:05:14.366[sip]   Call-ID: 0c8ae5ac-5181-1234-5681-a8f94b0e769a
13:05:14.366[sip]   CSeq: 231 REGISTER
13:05:14.366[sip]   Contact: <sip:7004@10.10.10.37:5060>
13:05:14.366[sip]   Expires: 120
13:05:14.366[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33024470 sofia-sip/1.12.10
13:05:14.366[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
13:05:14.366[sip]   Supported: timer, 100rel, replaces, path
13:05:14.366[sip]   Authorization: Digest username="7004", realm="sip3.line.ru", nonce="4861237c63c12b6b058abee55a42cc0b.1455876315", algorithm=MD5, uri="sip:91.215.252.131", response="41eb93112da477bc112961c09aef6eff"
13:05:14.366[sip]   Content-Length: 0
13:05:14.366[sip]
13:05:14.366[sip]   ------------------------------------------------------------------------
13:05:14.366[sip]nta: sent REGISTER (231) to udp/91.215.252.131:5060/sip
13:05:14.366[sip]tport_pend(0x255000): pending 0x31de00 for udp/10.10.10.37:5060 (already 0)
13:05:14.366[sip]nua(0x32d400): event r_register 100 Request Authorized by Cache
13:05:14.366[sip]nua: nua_application_event: entering
13:05:14.366[app:dbg]got nua_r_register : 100(Request Authorized by Cache)
13:05:14.366[app:dbg]sip: endpoint 5: REGISTER: 100 Request Authorized by Cache
13:05:14.366[app:dbg]Port 5: user port 3, old state hangup, new state
13:05:14.376[sip]tport_wakeup_pri(0x255000): events IN
13:05:14.376[sip]tport_recv_event(0x255000)
13:05:14.376[sip]tport_recv_iovec(0x255000) msg 0x339400 from (udp/10.10.10.37:5060) has 302 bytes, veclen = 1
13:05:14.376[sip]recv 302 bytes from udp/[91.215.252.131]:5060 at 02:10:09.790000:
13:05:14.376[sip]   ------------------------------------------------------------------------
13:05:14.376[sip]   SIP/2.0 100 Trying
13:05:14.376[sip]   Via: SIP/2.0/UDP 10.10.10.37:5060;rport=5060;branch=z9hG4bKFeg22c8rUj8NB;received=10.10.10.37
13:05:14.376[sip]   From: <sip:7004@91.215.252.131>;tag=X7F9gaXa2v0pD
13:05:14.376[sip]   To: <sip:7004@91.215.252.131>
13:05:14.376[sip]   Call-ID: 0c8ae5ac-5181-1234-5681-a8f94b0e769a
13:05:14.376[sip]   CSeq: 231 REGISTER
13:05:14.376[sip]   Server: ATC.PRO
13:05:14.376[sip]   Content-Length: 0
13:05:14.376[sip]
13:05:14.376[sip]   ------------------------------------------------------------------------
13:05:14.376[sip]tport_deliver(0x255000): msg 0x339400 (302 bytes) from udp/91.215.252.131:5060/sip next=(nil)
13:05:14.376[sip]nta: received 100 Trying for REGISTER (231)
13:05:14.376[sip]nta: 100 Trying is going to a transaction
13:05:14.376[sip]nta_outgoing: RTT is 10 ms
13:05:14.376[sip]tport_release(0x255000): 0x31de00 by 0x329300 with 0x339400 (preliminary)
13:05:14.376[sip]nua(0x32d400): event r_register 100 Trying
13:05:14.376[sip]nua: nua_application_event: entering
13:05:14.376[app:dbg]got nua_r_register : 100(Trying)
13:05:14.376[app:dbg]sip: endpoint 5: REGISTER: 100 Trying
13:05:14.376[app:dbg]Port 5: user port 3, old state hangup, new state
13:05:14.486[sip]tport_wakeup_pri(0x255000): events IN
13:05:14.486[sip]tport_recv_event(0x255000)
13:05:14.486[sip]tport_recv_iovec(0x255000) msg 0x31f400 from (udp/10.10.10.37:5060) has 451 bytes, veclen = 1
13:05:14.486[sip]recv 451 bytes from udp/[91.215.252.131]:5060 at 02:10:09.900000:
13:05:14.486[sip]   ------------------------------------------------------------------------
13:05:14.486[sip]   SIP/2.0 200 OK
13:05:14.486[sip]   Via: SIP/2.0/UDP 10.10.10.37:5060;rport=5060;branch=z9hG4bKFeg22c8rUj8NB;received=10.10.10.37
13:05:14.486[sip]   From: <sip:7004@91.215.252.131>;tag=X7F9gaXa2v0pD
13:05:14.486[sip]   To: <sip:7004@91.215.252.131>;tag=1040835811
13:05:14.486[sip]   Call-ID: 0c8ae5ac-5181-1234-5681-a8f94b0e769a
13:05:14.486[sip]   CSeq: 231 REGISTER
13:05:14.486[sip]   Expires: 120
13:05:14.486[sip]   Contact: <sip:7004@10.10.10.37:5060>;expires=120
13:05:14.486[sip]   Server: ATC.PRO
13:05:14.486[sip]   Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO, MESSAGE
13:05:14.486[sip]   Content-Length: 0
13:05:14.486[sip]
13:05:14.486[sip]   ------------------------------------------------------------------------
13:05:14.486[sip]tport_deliver(0x255000): msg 0x31f400 (451 bytes) from udp/91.215.252.131:5060/sip next=(nil)
13:05:14.486[sip]nta: received 200 OK for REGISTER (231)
13:05:14.486[sip]nta: 200 OK is going to a transaction
13:05:14.486[sip]tport_release(0x255000): 0x31de00 by 0x329300 with 0x31f400
13:05:14.486[sip]nua(): refresh register after 88 seconds (in [60..90])
13:05:14.486[sip]nua(): refresh register after 88 seconds
13:05:14.486[sip]nua(0x32d400): event r_register 200 OK
13:05:14.486[sip]nua: nua_application_event: entering
13:05:14.486[app:dbg]got nua_r_register : 200(OK)
13:05:14.486[app:dbg]sip: endpoint 5: REGISTER: 200 OK
13:05:14.486[app:dbg]Port 5: user port 3, old state hangup, new state
13:05:14.496[app:dbg]sip: endpoint 5: successfully registered
13:05:14.516[app:dbg]port 5: set led 1
13:05:14.516[app:dbg]Set port 5 led to state 'LED_OFF'
13:05:14.806[sip]nta: timer set next to 4550 ms
13:05:16.356[app:dbg]slic6. Event 8.
13:05:16.356[app:dbg]slic 6. Pre-On-hook event
13:05:16.356[app:dbg]HIO: preonhook TDM port '6', port enabled 1
13:05:17.236[app:dbg]slic6. Event 1.
13:05:17.236[app:dbg]slic 6. On-hook event
13:05:17.236[app:dbg]Set port 6 led to state 'LED_OFF'
13:05:17.236[app:dbg]HIO: onhook TDM port '6', port enabled 1
13:05:17.236[app:dbg]SLIC 6 (7001): onhook state: holding
13:05:17.236[app:dbg]regex ID 6: dial reset
13:05:17.236[app:dbg]SLIC 6: have call on hold
13:05:17.236[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 6
13:05:17.236[app:dbg]Port 6: check vapi queue ('free') at vapi_destroy_chan:890
13:05:17.236[app:dbg]Destroying connection 14...
13:05:17.236[app:dbg]Chan 14: current state is CREATED
13:05:17.236[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:916
13:05:17.236[app:dbg]VQ Conn 14 = MSP :       'destroy' =
13:05:17.236[app:dbg]Chan 14: CREATED -> DESTROYING
13:05:17.236[app:dbg]CMD_CREATE_CONN: port = 6
13:05:17.236[app:dbg]Port 6: check vapi queue ('busy''destroy') at vapi_create_chan:694
13:05:17.236[app:dbg]Port 6 put cmd 'create',cur 'destroy' to queue at (vapi_create_chan:700)
13:05:17.236[app:dbg]VQ Conn 6 = MSP :       'destroy' =
13:05:17.236[app:dbg]VQ Conn 6 + 05  :        'create'  + <-get_ptr
13:05:17.236[app:dbg]port 6: port_seize
13:05:17.236[app:dbg]port 6: seize
13:05:17.236[app:dbg]port 6: seize has cadence pulse = 0, pause = 0
13:05:17.236[app:dbg]Set port 6 led to state 'LED_RINGING'
13:05:17.236[app:dbg]Port 6: user port 0, old state ringing, new state
13:05:17.236[app:dbg]Set port 6 led to state 'LED_OFF'
13:05:17.236[app:dbg]pbx -[msg_fxs_state]-> group
13:05:17.236[app:dbg]Delete all RX-TX medias from SLIC 14
13:05:17.236[app:dbg]vapi_cb_req: 14 0 result 0x00000000 requid 0x0000014b
13:05:17.236[app:dbg]ITC: [msg_fxs_state] -> group
13:05:17.236[app:dbg]-----[GM] self_fxs_state()
13:05:17.236[app:dbg]Port 6: new state is ringing
13:05:17.256[app:dbg]Set port 6 led to state 'LED_OFF'
13:05:17.266[app:dbg]vapi_proc_event: VAPI_CB
13:05:17.266[app:dbg]vapi_cb_chan: chan 14 reqest_id 0x0000014b result 0x00000000
13:05:17.266[app:dbg]slic6. Event 6.
13:05:17.266[app:dbg]slic 6. Ring on event
13:05:17.266[app:dbg]Set port 6 led to state 'LED_RINGING'
13:05:17.266[app:dbg]vapi_cb_req: 14 0 result 0x00000000 requid 0x00000103
13:05:17.276[app:dbg]vapi_proc_event: VAPI_CB
13:05:17.276[app:dbg]vapi_cb_chan: chan 14 reqest_id 0x00000103 result 0x00000000
13:05:17.276[app:dbg]Conn 14 destroyed
13:05:17.276[app:dbg]Chan 14: DESTROYING -> INITIAL
13:05:17.276[app:dbg]Port 6: check vapi queue ('busy''destroy') at vapi_next_ops:2532
13:05:17.276[app:dbg]Port 6 get cmd 'create' from queue at (vapi_next_ops:2551)
13:05:17.276[app:dbg]Port 6: check vapi queue ('free') at vapi_create_chan:694
13:05:17.276[app:dbg]Chan 6: current state is CREATED
13:05:17.276[app:dbg]chan 6: no need to create - already exists
13:05:17.276[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2694
13:05:17.276[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:18.216[app:ERR]vapi_get_stats() can`t get statistic on chan:14 - connection in wrong state
13:05:18.216[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:328
13:05:18.216[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:18.266[app:dbg]slic6. Event 7.
13:05:18.266[app:dbg]slic 6. Ring off event
13:05:18.266[app:dbg]Set port 6 led to state 'LED_OFF'
13:05:18.266[app:dbg]Set port 6 led to state 'LED_OFF'
13:05:19.296[app:ERR]vapi_get_stats() can`t get statistic on chan:14 - connection in wrong state
13:05:19.296[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:328
13:05:19.296[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:19.366[sip]nta: timer K fired, terminate REGISTER (230)
13:05:19.366[sip]outgoing_reclaim_all((nil), (nil), 0xbd5ffcc4)
13:05:19.366[sip]nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/3 term, 1/4 free
13:05:19.366[sip]nta: timer set next to 120 ms
13:05:19.496[sip]nta: timer K fired, terminate REGISTER (231)
13:05:19.496[sip]outgoing_reclaim_all((nil), (nil), 0xbd5ffcc4)
13:05:19.496[sip]nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free
13:05:19.496[sip]nta: timer set next to 16410 ms
13:05:20.376[app:ERR]vapi_get_stats() can`t get statistic on chan:14 - connection in wrong state
13:05:20.376[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:328
13:05:20.376[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:21.456[app:ERR]vapi_get_stats() can`t get statistic on chan:14 - connection in wrong state
13:05:21.456[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:328
13:05:21.456[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:22.256[app:dbg]slic6. Event 6.
13:05:22.256[app:dbg]slic 6. Ring on event
13:05:22.256[app:dbg]Set port 6 led to state 'LED_RINGING'
13:05:22.536[app:ERR]vapi_get_stats() can`t get statistic on chan:14 - connection in wrong state
13:05:22.536[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:328
13:05:22.536[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:23.246[app:dbg]slic6. Event 7.
13:05:23.246[app:dbg]slic 6. Ring off event
13:05:23.246[app:dbg]Set port 6 led to state 'LED_OFF'
13:05:23.246[app:dbg]Set port 6 led to state 'LED_OFF'
13:05:23.616[app:ERR]vapi_get_stats() can`t get statistic on chan:14 - connection in wrong state
13:05:23.616[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:328
13:05:23.616[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:24.696[app:ERR]vapi_get_stats() can`t get statistic on chan:14 - connection in wrong state
13:05:24.696[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:328
13:05:24.696[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:25.776[app:ERR]vapi_get_stats() can`t get statistic on chan:14 - connection in wrong state
13:05:25.776[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:328
13:05:25.776[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:26.856[app:ERR]vapi_get_stats() can`t get statistic on chan:14 - connection in wrong state
13:05:26.856[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:328
13:05:26.856[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:27.266[app:dbg]slic6. Event 6.
13:05:27.266[app:dbg]slic 6. Ring on event
13:05:27.266[app:dbg]Set port 6 led to state 'LED_RINGING'
13:05:27.276[sip]tport_wakeup_pri(0x255000): events IN
13:05:27.276[sip]tport_recv_event(0x255000)
13:05:27.276[sip]tport_recv_iovec(0x255000) msg 0x31f400 from (udp/10.10.10.37:5060) has 477 bytes, veclen = 1
13:05:27.276[sip]recv 477 bytes from udp/[91.215.252.131]:5060 at 02:10:22.690000:
13:05:27.276[sip]   ------------------------------------------------------------------------
13:05:27.276[sip]   BYE sip:7001@10.10.10.37:5060 SIP/2.0
13:05:27.276[sip]   Call-ID: 1742192132@10.10.10.245
13:05:27.276[sip]   From: <sip:3465265@10.10.10.245>;tag=1135724852
13:05:27.276[sip]   To: <sip:7001@10.10.10.37:5060>;tag=j52Hp2ym5QmZg
13:05:27.276[sip]   Reason: SIP;cause=486;text="Busy Here"
13:05:27.276[sip]   P-RTP-Stat: PS=1147,OS=183520,PR=0,OR=0,PL=0
13:05:27.276[sip]   Via: SIP/2.0/UDP 91.215.252.131:5060;rport;branch=z9hG4bK1393735674
13:05:27.276[sip]   CSeq: 259 BYE
13:05:27.276[sip]   User-Agent: ATC.PRO
13:05:27.276[sip]   Max-Forwards: 70
13:05:27.276[sip]   Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO, MESSAGE
13:05:27.276[sip]   Content-Length: 0
13:05:27.276[sip]
13:05:27.276[sip]   ------------------------------------------------------------------------
13:05:27.276[sip]tport_deliver(0x255000): msg 0x31f400 (477 bytes) from udp/91.215.252.131:5060/sip next=(nil)
13:05:27.276[sip]nta: received BYE sip:7001@10.10.10.37:5060 SIP/2.0 (CSeq 259)
13:05:27.276[sip]nta: canonizing sip:7001@10.10.10.37:5060 with contact
13:05:27.276[sip]nta: BYE (259) going to existing leg
13:05:27.276[sip]nua: nua_stack_process_request: entering
13:05:27.276[sip]nua(0x32bd00): event i_bye 100 Trying
13:05:27.276[sip]nua: nua_application_event: entering
13:05:27.276[app:dbg]got nua_i_bye : 100(Trying)
13:05:27.276[sip]nua: nua_respond: entering
13:05:27.276[sip]nua(0x32bd00): sent signal r_respond
13:05:27.276[sip]nua(0x32bd00): recv signal r_respond 200 OK
13:05:27.276[sip]nua: nua_stack_set_params: entering
13:05:27.276[sip]soa_set_params(static::0x32c100, ...) called
13:05:27.286[sip]tport_tsend(0x255000) tpn = UDP/91.215.252.131:5060
13:05:27.286[sip]tport_resolve addrinfo = 91.215.252.131:5060
13:05:27.286[sip]tport_by_addrinfo(0x255000): not found by name UDP/91.215.252.131:5060
13:05:27.286[sip]tport_vsend(0x255000): 517 bytes of 517 to udp/91.215.252.131:5060
13:05:27.286[sip]tport_vsend returned 517
13:05:27.286[sip]send 517 bytes to udp/[91.215.252.131]:5060 at 02:10:22.700000:
13:05:27.286[sip]   ------------------------------------------------------------------------
13:05:27.286[sip]   SIP/2.0 200 OK
13:05:27.286[sip]   Via: SIP/2.0/UDP 91.215.252.131:5060;rport=5060;branch=z9hG4bK1393735674
13:05:27.286[sip]   From: <sip:3465265@10.10.10.245>;tag=1135724852
13:05:27.286[sip]   To: <sip:7001@10.10.10.37:5060>;tag=j52Hp2ym5QmZg
13:05:27.286[sip]   Call-ID: 1742192132@10.10.10.245
13:05:27.286[sip]   CSeq: 259 BYE
13:05:27.286[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33024470 sofia-sip/1.12.10
13:05:27.286[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
13:05:27.286[sip]   Supported: timer, 100rel, replaces
13:05:27.286[sip]   Content-Length: 0
13:05:27.286[sip]   P-RTP-Stat: PS=120, OS=20322, PR=717, OR=123324, PL=0, JI=155
13:05:27.286[sip]
13:05:27.286[sip]   ------------------------------------------------------------------------
13:05:27.286[sip]nta: sent 200 OK for BYE (259)
13:05:27.286[sip]nua(0x32bd00): removing session usage
13:05:27.286[sip]nua(0x32bd00): call state changed: ready -> terminated
13:05:27.286[sip]nua(0x32bd00): event i_state 200 Session Terminated
13:05:27.286[sip]nua: nua_application_event: entering
13:05:27.286[app:dbg]got nua_i_state : 200(Session Terminated)
13:05:27.286[app:dbg]NO SIP IN nua_i_state == 200 : Session Terminated
13:05:27.286[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
13:05:27.286[app:dbg]sip: call 02060005: terminated
13:05:27.286[app:dbg]7011: endpoint 6 set to busy
13:05:27.286[app:dbg]sip -[msg_clear]-> pbx
13:05:27.286[app:dbg]self_callstate_terminated: call id = 02060005 need_exchange_at_answer = 0
13:05:27.286[sip]nua: nua_handle_destroy: entering
13:05:27.286[sip]nua(0x32bd00): sent signal r_destroy
13:05:27.286[app:dbg]ITC: [msg_clear] -> pbx
13:05:27.286[app:dbg]dump_port_calls() SLIC 6:
13:05:27.286[app:dbg]Q:NONE
13:05:27.286[app:dbg]H:(0x314000,0x02060005,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
13:05:27.286[app:dbg]SLIC 6: peer cleared(02060005)
13:05:27.286[app:dbg]SLIC 6: hold call cleared
13:05:27.286[app:dbg]vapi: chan 6: connection STATISTIC
13:05:27.286[app:dbg]vapi: chan 6: Rx_pack = 771
13:05:27.286[app:dbg]vapi: chan 6: Rx_oct  = 132612
13:05:27.286[app:dbg]vapi: chan 6: Lost_pack  = 0
13:05:27.286[app:dbg]vapi: chan 6: Tx_pack = 120
13:05:27.286[app:dbg]vapi: chan 6: Tx_oct  = 20322
13:05:27.286[app:dbg]vapi: chan 6: peak_jiter = 155
13:05:27.286[app:dbg]SLIC 6: Common port statistic
13:05:27.286[app:dbg]SLIC 6: Rx_pack = 37539
13:05:27.286[app:dbg]SLIC 6: Rx_oct  = 9156308
13:05:27.286[app:dbg]SLIC 6: Lost_pack  = 0
13:05:27.286[app:dbg]SLIC 6: Tx_pack = 31792
13:05:27.286[app:dbg]SLIC 6: Tx_oct  = 7650180
13:05:27.286[app:dbg]SLIC 6: peak_jiter = 155
13:05:27.286[app:dbg]SLIC 6: reset call 0x02060005 (hold)
13:05:27.286[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 6
13:05:27.286[app:dbg]Port 6: check vapi queue ('free') at vapi_destroy_chan:890
13:05:27.286[app:dbg]Destroying connection 14...
13:05:27.286[app:dbg]Chan 14: current state is INITIAL
13:05:27.286[app:ERR]vapi_destroy_chan() chan 14: current state initial: duplicate destroying connection!
13:05:27.286[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:320
13:05:27.286[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:27.296[sip]nua(0x32bd00): event i_terminated 200 Session Terminated
13:05:27.296[sip]soa_destroy(static::0x32c100) called
13:05:27.296[sip]nta_leg_destroy(0x29a980)
13:05:27.296[sip]nua(0x32bd00): recv signal r_destroy
13:05:27.296[sip]nua: nh_destroy: entering
13:05:27.296[sip]nta_leg_destroy((nil))
13:05:27.316[app:dbg]incom_calls_rem() rem call 0x02060005, group -1, task <sip> from list
13:05:27.316[app:dbg]SLIC 6 have no calls after hold call cleared
13:05:27.316[app:dbg]port 6: clear
13:05:27.316[app:dbg]Set port 6 led to state 'LED_OFF'
13:05:27.316[app:dbg]CMD_STOP_TONE: port = 6
13:05:27.316[app:dbg]Port 6: check vapi queue ('free') at vapi_stop_tone_chan:1474
13:05:27.316[app:dbg]Chan 6: current state is CREATED
13:05:27.316[app:ERR]chan 6: no generated tones!
13:05:27.316[app:dbg]vapi_chan.c:1510: conn 6 peek cmd 'no event' from queue
13:05:27.316[app:dbg]Port 6: check vapi queue ('free') at __cmd_engine:320
13:05:27.316[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:27.316[app:dbg]SLIC 6: reset
13:05:27.316[app:dbg]dump_port_calls() SLIC 6:
13:05:27.316[app:dbg]Q:NONE
13:05:27.316[app:dbg]H:((nil),0x00000000,(nil),1) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
13:05:27.316[app:dbg]Delete all RX-TX medias from SLIC 6
13:05:27.316[app:dbg]free_final_mx: final_mx was NULL for SLIC 6
13:05:27.316[app:dbg]CMD_DESTROY_CONN: port = 6
13:05:27.316[app:dbg]Port 6: check vapi queue ('free') at vapi_destroy_chan:890
13:05:27.316[app:dbg]Destroying connection 6...
13:05:27.316[app:dbg]Chan 6: current state is CREATED
13:05:27.316[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:916
13:05:27.316[app:dbg]VQ Conn 6 = MSP :       'destroy' =
13:05:27.316[app:dbg]Chan 6: CREATED -> DESTROYING
13:05:27.316[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000014b
13:05:27.316[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 6
13:05:27.316[app:dbg]Port 6: check vapi queue ('busy''destroy') at vapi_destroy_chan:890
13:05:27.316[app:dbg]Clear vapi queue of Port 6/chan 14
13:05:27.316[app:dbg]Port 6 put cmd 'destroy',cur 'destroy' to queue at (vapi_destroy_chan:897)
13:05:27.316[app:dbg]VQ Conn 14 = MSP :       'destroy' =
13:05:27.316[app:dbg]VQ Conn 14 + 00  :       'destroy' (hold) + <-get_ptr
13:05:27.316[app:dbg]Port 6: user port 0, old state hangup, new state
13:05:27.316[app:dbg]Set port 6 led to state 'LED_OFF'
13:05:27.316[app:dbg]pbx -[msg_fxs_state]-> group
13:05:27.316[app:dbg]ITC: [msg_fxs_state] -> group
13:05:27.316[app:dbg]-----[GM] self_fxs_state()
13:05:27.316[app:dbg]Port 6: new state is hangup
13:05:27.326[app:dbg]Delete all RX-TX medias from SLIC 14
13:05:27.336[app:dbg]Delete all RX-TX medias from SLIC 6
13:05:27.336[app:dbg]Port 6: user port 0, old state hangup, new state
13:05:27.336[app:dbg]dump_port_calls() SLIC 6:
13:05:27.336[app:dbg]Q:NONE
13:05:27.336[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
13:05:27.336[app:dbg]vapi_proc_event: VAPI_CB
13:05:27.336[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000014b result 0x00000000
13:05:27.336[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000103
13:05:27.346[app:dbg]vapi_proc_event: VAPI_CB
13:05:27.346[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000103 result 0x00000000
13:05:27.346[app:dbg]Conn 6 destroyed
13:05:27.346[app:dbg]Chan 6: DESTROYING -> INITIAL
13:05:27.346[app:dbg]Port 6: check vapi queue ('busy''destroy') at vapi_next_ops:2532
13:05:27.346[app:dbg]Port 6 get cmd 'destroy' from queue at (vapi_next_ops:2551)
13:05:27.346[app:dbg]Port 6: check vapi queue ('free') at vapi_destroy_chan:890
13:05:27.346[app:dbg]Destroying connection 14...
13:05:27.346[app:dbg]Chan 14: current state is INITIAL
13:05:27.346[app:ERR]vapi_destroy_chan() chan 14: current state initial: duplicate destroying connection!
13:05:27.346[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2694
13:05:27.346[app:dbg]Port 6: check vapi queue ('free') at vapi_next_ops:2532
13:05:35.916[sip]nta: timer D fired, terminate INVITE (3899)
13:05:35.916[sip]nta: timer F fired, terminating ACK (3899)
13:05:35.916[sip]outgoing_reclaim_all((nil), (nil), 0xbd5ffcc4)
13:05:35.916[sip]nta_outgoing_timer: 0/0 resent, 1/1 tout, 1/1 term, 2/2 free
13:05:35.916[sip]nta: timer set next to 23370 ms
13:05:40.466[app:dbg]app: REINIT
13:05:40.476[app:dbg]Getting option 'enable' in section 'pbx'
13:05:40.476[app:dbg]Founded value: 0
13:05:40.476[app:dbg]Getting option 'sip_level' in section 'pbx'
13:05:40.476[app:dbg]Founded value: 5
13:04:51.126[app:dbg]Getting option 'cadence' in section 'calling_number9'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: 1000,4000
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'name' in section 'calling_number9'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: cadence9
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'enable' in section 'calling_number9'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: 0
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]calling number index = 10
-ash: 13:04:51.126[app:dbg]calling: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'calling_number' in section 'calling_number10'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'cadence' in section 'calling_number10'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: 1000,4000
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'name' in section 'calling_number10'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: cadence10
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'enable' in section 'calling_number10'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: 0
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]calling number index = 11
-ash: 13:04:51.126[app:dbg]calling: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'calling_number' in section 'calling_number11'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'cadence' in section 'calling_number11'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: 1000,4000
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'name' in section 'calling_number11'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: cadence11
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'enable' in section 'calling_number11'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: 0
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]calling number index = 12
-ash: 13:04:51.126[app:dbg]calling: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'calling_number' in section 'calling_number12'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'cadence' in section 'calling_number12'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: 1000,4000
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'name' in section 'calling_number12'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: cadence12
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'enable' in section 'calling_number12'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: 0
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]calling number index = 13
-ash: 13:04:51.126[app:dbg]calling: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'calling_number' in section 'calling_number13'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'cadence' in section 'calling_number13'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: 1000,4000
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'name' in section 'calling_number13'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: cadence13
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'enable' in section 'calling_number13'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: 0
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]calling number index = 14
-ash: 13:04:51.126[app:dbg]calling: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'calling_number' in section 'calling_number14'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'cadence' in section 'calling_number14'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: 1000,4000
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Getting option 'name' in section 'calling_number14'
-ash: 13:04:51.126[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.126[app:dbg]Founded value: cadence14
-ash: 13:04:51.126[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'enable' in section 'calling_number14'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: 0
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]calling number index = 15
-ash: 13:04:51.166[app:dbg]calling: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'calling_number' in section 'calling_number15'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'cadence' in section 'calling_number15'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: 1000,4000
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'name' in section 'calling_number15'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: cadence15
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'enable' in section 'calling_number15'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: 0
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]calling number index = 16
-ash: 13:04:51.166[app:dbg]calling: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'calling_number' in section 'calling_number16'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'cadence' in section 'calling_number16'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: 1000,4000
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'name' in section 'calling_number16'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: cadence16
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'enable' in section 'calling_number16'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: 0
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]calling number index = 17
-ash: 13:04:51.166[app:dbg]calling: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'calling_number' in section 'calling_number17'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'cadence' in section 'calling_number17'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: 1000,4000
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'name' in section 'calling_number17'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: cadence17
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'enable' in section 'calling_number17'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: 0
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]calling number index = 18
-ash: 13:04:51.166[app:dbg]calling: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'calling_number' in section 'calling_number18'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'cadence' in section 'calling_number18'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: 1000,4000
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'name' in section 'calling_number18'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: cadence18
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'enable' in section 'calling_number18'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: 0
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]calling number index = 19
-ash: 13:04:51.166[app:dbg]calling: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'calling_number' in section 'calling_number19'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'cadence' in section 'calling_number19'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: 1000,4000
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'name' in section 'calling_number19'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: cadence19
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Getting option 'enable' in section 'calling_number19'
-ash: 13:04:51.166[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.166[app:dbg]Founded value: 0
-ash: 13:04:51.166[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.166[app:WARN]There is no command settings section!
-ash: 13:04:51.166[app:WARN]There: not found
root@TAU-8:~# 13:04:51.186[app:dbg]Getting option 'network_mode' in section 'common_settings'
-ash: 13:04:51.186[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.186[app:dbg]Founded value: advanced
-ash: 13:04:51.186[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Getting option 'service_count' in section 'common_settings'
-ash: 13:04:51.206[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Getting option 'service_name' in section 'service0'
-ash: 13:04:51.206[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Founded value: Internet
-ash: 13:04:51.206[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Getting option 'type_lan0' in section 'service0'
-ash: 13:04:51.206[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Getting option 'type_lan1' in section 'service0'
-ash: 13:04:51.206[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Getting option 'type_lan2' in section 'service0'
-ash: 13:04:51.206[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Getting option 'type_lan3' in section 'service0'
-ash: 13:04:51.206[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Getting option 'connection' in section 'service0'
-ash: 13:04:51.206[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Getting option 'bridge_mode' in section 'service0'
-ash: 13:04:51.206[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Getting option 'wan_type' in section 'service0'
-ash: 13:04:51.206[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Founded value: Untagged
-ash: 13:04:51.206[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Getting option 'vlan_id' in section 'service0'
-ash: 13:04:51.206[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Getting option 'wan_protocol' in section 'service0'
-ash: 13:04:51.206[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Founded value: DHCP
-ash: 13:04:51.206[app:dbg]Founded: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Getting option 'ipsec_enable' in section 'service0'
-ash: 13:04:51.206[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.206[app:dbg]net_config_init: Signalling interface eth0
-ash: 13:04:51.206[app:dbg]net_config_init:: not found
root@TAU-8:~# 13:04:51.206[app:dbg]net: init: local IP: 10.10.10.37
-ash: 13:04:51.206[app:dbg]net:: not found
root@TAU-8:~# 13:04:51.206[app:dbg]net: init: local MAC: a8:f9:4b:0e:76:9a
-ash: 13:04:51.206[app:dbg]net:: not found
root@TAU-8:~# 13:04:51.206[app:dbg]Signalling IP is 10.10.10.37
-ash: 13:04:51.206[app:dbg]Signalling: not found
root@TAU-8:~# 13:04:51.206[app:dbg]net: init: local IP: 10.10.10.37
-ash: 13:04:51.206[app:dbg]net:: not found
root@TAU-8:~# 13:04:51.206[app:dbg]net: init: local MAC: a8:f9:4b:0e:76:9a
-ash: 13:04:51.206[app:dbg]net:: not found
root@TAU-8:~# 13:04:51.206[app:dbg]RTP IP is 10.10.10.37
-ash: 13:04:51.206[app:dbg]RTP: not found
root@TAU-8:~# 13:04:51.226[app:dbg]Getting option 'reserved_ip' in section 'qos'-ash: 13:04:51.226[app:dbg]Getting: not found
root@TAU-8:~# 13:04:51.226[app:dbg]Founded value: 192.168.253.1
-ash: 13:04:51.226[app:dbg]Founded: not found
root@TAU-8:~# 13:04:54.116[sip]nta: timer K fired, terminate REGISTER (228)
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:54.116[sip]outgoing_reclaim_all((nil), (nil), 0xbd5ffcc4)
-ash: Syntax error: "(" unexpected (expecting ")")
root@TAU-8:~# 13:04:54.116[sip]nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free
-ash: 13:04:54.116[sip]nta_outgoing_timer:: not found
root@TAU-8:~# 13:04:54.116[sip]nta: timer set next to 130 ms
-ash: 13:04:54.116[sip]nta:: not found
root@TAU-8:~# 13:04:54.256[sip]nta: timer K fired, terminate REGISTER (229)
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:54.256[sip]outgoing_reclaim_all((nil), (nil), 0xbd5ffcc4)
-ash: Syntax error: "(" unexpected (expecting ")")
root@TAU-8:~# 13:04:54.256[sip]nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free
-ash: 13:04:54.256[sip]nta_outgoing_timer:: not found
root@TAU-8:~# 13:04:54.256[sip]nta: timer not set
-ash: 13:04:54.256[sip]nta:: not found
root@TAU-8:~# 13:04:58.656[sip]tport_wakeup_pri(0x255000): events IN
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.656[sip]tport_recv_event(0x255000)
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.656[sip]tport_recv_iovec(0x255000) msg 0x31f400 from (udp/10.10.10.37:5060) has 713 bytes, veclen = 1
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.656[sip]recv 713 bytes from udp/[91.215.252.131]:5060 at 02:09:54.070000:
-ash: 13:04:58.656[sip]recv: not found
root@TAU-8:~# 13:04:58.656[sip]   ------------------------------------------------------------------------
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   INVITE sip:7001@10.10.10.37:5060 SIP/2.0
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   Max-Forwards: 20
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   Via: SIP/2.0/UDP 91.215.252.131:5060;rport;branch=z9hG4bK858035671
-ash: 13:04:58.656[sip]: not found
-ash: rport: not found
root@TAU-8:~# 13:04:58.656[sip]   From: <sip:3465265@10.10.10.245>;tag=1135724852
-ash: Syntax error: ";" unexpected
root@TAU-8:~# 13:04:58.656[sip]   To: <sip:7001@10.10.10.37:5060>
-ash: Syntax error: newline unexpected
root@TAU-8:~# 13:04:58.656[sip]   Call-ID: 1742192132@10.10.10.245
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   CSeq: 258 INVITE
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   User-Agent: ATC.PRO
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   Contact: <sip:3465265@91.215.252.131:5060>
-ash: Syntax error: newline unexpected
root@TAU-8:~# 13:04:58.656[sip]   Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO, MESSAGE
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   Content-Type: application/sdp
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   Content-Length: 258
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   v=0
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   o=yate 1455876300 1455876300 IN IP4 91.215.252.131
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   s=SIP Call
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   c=IN IP4 91.215.252.131
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   t=0 0
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   m=audio 23170 RTP/AVP 8 4 18 101
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   a=rtpmap:8 PCMA/8000
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   a=rtpmap:4 G723/8000
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   a=rtpmap:18 G729/8000
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   a=fmtp:18 annexb=no
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   a=rtpmap:101 telephone-event/8000
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]   ------------------------------------------------------------------------
-ash: 13:04:58.656[sip]: not found
root@TAU-8:~# 13:04:58.656[sip]tport_deliver(0x255000): msg 0x31f400 (713 bytes) from udp/91.215.252.131:5060/sip next=(nil)
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.656[sip]nta: received INVITE sip:7001@10.10.10.37:5060 SIP/2.0 (CSeq 258)
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:58.656[sip]nta: canonizing sip:7001@10.10.10.37:5060 with contact
-ash: 13:04:58.656[sip]nta:: not found
root@TAU-8:~# 13:04:58.656[sip]nta: INVITE (258) going to a default leg
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:58.656[sip]nta: timer set to 200 ms
-ash: 13:04:58.656[sip]nta:: not found
root@TAU-8:~# 13:04:58.656[sip]nua: nua_stack_process_request: entering
-ash: 13:04:58.656[sip]nua:: not found
root@TAU-8:~# 13:04:58.656[app:dbg]self_pre_invite_param() entering
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.656[app:dbg]stun_get_public_ip(port = 8000)
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.656[app:dbg]stun_get_public_ip: Always using local IP
-ash: 13:04:58.656[app:dbg]stun_get_public_ip:: not found
root@TAU-8:~# 13:04:58.656[app:dbg]sip: simple call (6) profile(0)
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:58.656[app:dbg]sip: get_support_params: profile 0 supported: 'timer, 100rel, replaces'
-ash: 13:04:58.656[app:dbg]sip:: not found
root@TAU-8:~# 13:04:58.666[sip]nua: nua_stack_process_request: nua_pre_invite_param: profile_supported_str: 'timer, 100rel, replaces' min_se: 120
-ash: 13:04:58.666[sip]nua:: not found
root@TAU-8:~# 13:04:58.666[sip]nua: nua_stack_incoming_handle: entering
-ash: 13:04:58.666[sip]nua:: not found
root@TAU-8:~# 13:04:58.666[sip]nua: nh_create: entering
-ash: 13:04:58.666[sip]nua:: not found
root@TAU-8:~# 13:04:58.666[sip]nua: nh_create_handle: entering
-ash: 13:04:58.666[sip]nua:: not found
root@TAU-8:~# 13:04:58.666[sip]nua: nua_stack_set_params: entering
-ash: 13:04:58.666[sip]nua:: not found
root@TAU-8:~# 13:04:58.666[sip]soa_clone(static::0x2fec00, 0x2e7f80, 0x32bd00) called
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[sip]soa_set_params(static::0x32c100, ...) called
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[sip]soa_set_params(static::0x32c100, ...) called
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[sip]nta_leg_tcreate(0x29a980)
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[sip]soa_init_offer_answer(static::0x32c100) called
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[sip]soa_set_remote_sdp(static::0x32c100, (nil), 0x3169c7, 258) called
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[sip]nua(0x32bd00): adding session usage
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[sip]tport_tsend(0x255000) tpn = UDP/91.215.252.131:5060
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[sip]tport_resolve addrinfo = 91.215.252.131:5060
-ash: 13:04:58.666[sip]tport_resolve: not found
root@TAU-8:~# 13:04:58.666[sip]tport_by_addrinfo(0x255000): not found by name UDP/91.215.252.131:5060
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[sip]tport_vsend(0x255000): 308 bytes of 308 to udp/91.215.252.131:5060
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[sip]tport_vsend returned 308
-ash: 13:04:58.666[sip]tport_vsend: not found
root@TAU-8:~# 13:04:58.666[sip]send 308 bytes to udp/[91.215.252.131]:5060 at 02:09:54.080000:
-ash: 13:04:58.666[sip]send: not found
root@TAU-8:~# 13:04:58.666[sip]   ------------------------------------------------------------------------
-ash: 13:04:58.666[sip]: not found
root@TAU-8:~# 13:04:58.666[sip]   SIP/2.0 100 Trying
-ash: 13:04:58.666[sip]: not found
root@TAU-8:~# 13:04:58.666[sip]   Via: SIP/2.0/UDP 91.215.252.131:5060;rport=5060;branch=z9hG4bK858035671
-ash: 13:04:58.666[sip]: not found
root@TAU-8:~# 13:04:58.666[sip]   From: <sip:3465265@10.10.10.245>;tag=1135724852
-ash: Syntax error: ";" unexpected
root@TAU-8:~# 13:04:58.666[sip]   To: <sip:7001@10.10.10.37:5060>
-ash: Syntax error: newline unexpected
root@TAU-8:~# 13:04:58.666[sip]   Call-ID: 1742192132@10.10.10.245
-ash: 13:04:58.666[sip]: not found
root@TAU-8:~# 13:04:58.666[sip]   CSeq: 258 INVITE
-ash: 13:04:58.666[sip]: not found
root@TAU-8:~# 13:04:58.666[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33024470 sofia-sip/1.12.10
-ash: 13:04:58.666[sip]: not found
root@TAU-8:~# 13:04:58.666[sip]   Content-Length: 0
-ash: 13:04:58.666[sip]: not found
root@TAU-8:~# 13:04:58.666[sip]
-ash: 13:04:58.666[sip]: not found
root@TAU-8:~# 13:04:58.666[sip]   ------------------------------------------------------------------------
-ash: 13:04:58.666[sip]: not found
root@TAU-8:~# 13:04:58.666[sip]nta: sent 100 Trying for INVITE (258)
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:58.666[sip]nua(0x32bd00): event i_invite 100 Trying
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[sip]nua: nua_application_event: entering
-ash: 13:04:58.666[sip]nua:: not found
root@TAU-8:~# 13:04:58.666[app:dbg]got nua_i_invite : 100(Trying)
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:58.666[app:dbg]NO CALL IN nua_i_invite == 100 : Trying
-ash: 13:04:58.666[app:dbg]NO: not found
root@TAU-8:~# 13:04:58.666[app:dbg]stun_get_public_ip(port = 8000)
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[app:dbg]stun_get_public_ip: Always using local IP
-ash: 13:04:58.666[app:dbg]stun_get_public_ip:: not found
root@TAU-8:~# 13:04:58.666[app:dbg]sip: get_support_params: profile 0 supported: 'timer, 100rel, replaces'
-ash: 13:04:58.666[app:dbg]sip:: not found
root@TAU-8:~# 13:04:58.666[app:dbg]sip: INVITE from sip:3465265@10.10.10.245
-ash: 13:04:58.666[app:dbg]sip:: not found
root@TAU-8:~# 13:04:58.666[app:dbg]simple call
-ash: 13:04:58.666[app:dbg]simple: not found
root@TAU-8:~# 13:04:58.666[app:dbg]stun_get_public_ip(port = 8000)
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.676[sip]nua(0x32bd00): call state changed: init -> received, received offer
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.676[sip]soa_get_remote_sdp(static::0x32c100, [0xbd5ff804], [0xbd5ff800], [(nil)]) called
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.676[sip]nua(0x32bd00): event i_state 100 Trying
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.666[app:dbg]stun_get_public_ip: Always using local IP
-ash: 13:04:58.666[app:dbg]stun_get_public_ip:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]replaces 1, have accepted 0, ep 0x1b9330, state 1
-ash: 13:04:58.676[app:dbg]replaces: not found
root@TAU-8:~# 13:04:58.676[app:dbg]available RTP ports: 23000...26000
-ash: 13:04:58.676[app:dbg]available: not found
root@TAU-8:~# 13:04:58.676[app:dbg]selected port for current call: 23072
-ash: 13:04:58.676[app:dbg]selected: not found
root@TAU-8:~# 13:04:58.676[app:dbg]self_i_invite (8694): no alert_info received
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_init() init call sdp (empty)
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_set_ssup() ssup present 0 ssup yes-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]G711A: PT 8
-ash: 13:04:58.676[app:dbg]G711A:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_add_g711a_item() pt 8
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]G723: PT 4, bitrate default, annexa default
-ash: 13:04:58.676[app:dbg]G723:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_add_g723_item() pt 4, rate absent 6.3 ssup absent on
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_set_rfc2833() wrong param fmtp, set fmtp default '0-15'
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_set_rfc2833() present pt 101 remote fmtp 0-15, local fmtp 0-15
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_dump() ssup absent on, ecan absent on, rfc present 101, nse absent 0, ptime absent 0
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_dump() G723:
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_dump() PT 4, rate absent 6.3, ssup absent on
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_dump() G711A:
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_dump() G711U: none
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]stun_get_public_ip(port = 23072)
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.676[app:dbg]stun_get_public_ip: Always using local IP
-ash: 13:04:58.676[app:dbg]stun_get_public_ip:: not found
root@TAU-8:~# 13:04:58.676[sip]nua: nua_set_hparams: entering
-ash: 13:04:58.676[sip]nua:: not found
root@TAU-8:~# 13:04:58.676[sip]nua(0x32bd00): recv signal r_set_params
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.676[sip]nua: nua_stack_set_params: entering
-ash: 13:04:58.676[sip]nua:: not found
root@TAU-8:~# 13:04:58.676[sip]soa_set_params(static::0x32c100, ...) called
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.676[sip]soa_base_set_params: NOT reduce media: soa_session(:0x32c100, ...) called
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:58.676[sip]nua(0x32bd00): event r_set_params 200 OK
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.676[sip]nua(0x32bd00): sent signal r_set_params
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.676[sip]nua: nua_handle_bind: entering
-ash: 13:04:58.676[sip]nua:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]self_i_invite: handle call id 0x02060005, call id 0x02060005
-ash: 13:04:58.676[app:dbg]self_i_invite:: not found
root@TAU-8:~# 13:04:58.676[sip]nua: nua_application_event: entering
-ash: 13:04:58.676[sip]nua:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]got nua_i_state : 100(Trying)
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:58.676[app:dbg]NO SIP IN nua_i_state == 100 : Trying
-ash: 13:04:58.676[app:dbg]NO: not found
root@TAU-8:~# 13:04:58.676[app:dbg]self_i_state(): call state 5: or : remote sdp : sdp_init no_oc
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sip: call 02060005: SDP offer received
-ash: 13:04:58.676[app:dbg]sip:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_init() init call sdp (offer)
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_set_ssup() ssup present 0 ssup yes-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_set_rfc2833() wrong param fmtp, set fmtp default '0-15'
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_set_rfc2833() present pt 101 remote fmtp 0-15, local fmtp 0-15
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.676[app:dbg]sip: call 02060005: media stream 0, creating proposed audio channel, remote RTP 91.215.252.131:23170
-ash: 13:04:58.676[app:dbg]sip:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]sip: call 02060005: select audio media
-ash: 13:04:58.676[app:dbg]sip:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]G711A: PT 8
-ash: 13:04:58.676[app:dbg]G711A:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]G723: PT 4
-ash: 13:04:58.676[app:dbg]G723:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]sip: call 02060005: remote SDP offer copy
-ash: 13:04:58.676[app:dbg]sip:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]sip: call 02060005: called from sip:3465265@10.10.10.245 to sip:7001@10.10.10.37:5060
-ash: 13:04:58.676[app:dbg]sip:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
-ash: 13:04:58.676[app:dbg]sdp_codecs_get_rfc2833:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]sip -[msg_call]-> pbx
-ash: cannot create pbx: Read-only file system
-ash: 13:04:58.676[app:dbg]sip: not found
root@TAU-8:~# 13:04:58.676[app:dbg]ITC: [msg_call] -> pbx
-ash: cannot create pbx: Read-only file system
-ash: 13:04:58.676[app:dbg]ITC:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]SLIC 6: incoming call from 10.10.10.245:5060/3465265("unknown") payload 101 call ID: 02060005 group: -1
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:58.676[app:dbg]pbx: allocating memory for new call
-ash: 13:04:58.676[app:dbg]pbx:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]pbx: created new incoming call for SLIC 6
-ash: 13:04:58.676[app:dbg]pbx:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]self_call_create (4455): created
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.676[app:dbg]SLIC 6: -> ringing
-ash: cannot create ringing: Read-only file system
-ash: 13:04:58.676[app:dbg]SLIC: not found
root@TAU-8:~# 13:04:58.676[app:dbg]CMD_CREATE_CONN: port = 6
-ash: 13:04:58.676[app:dbg]CMD_CREATE_CONN:: not found
root@TAU-8:~# 13:04:58.676[app:dbg]Port 6: check vapi queue ('free') at vapi_create_chan:694
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:58.676[app:dbg]Chan 6: current state is INITIAL
-ash: 13:04:58.676[app:dbg]Chan: not found
root@TAU-8:~# 13:04:58.676[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'create' at vapi_create_chan:720
-ash: 13:04:58.676[app:dbg]Port: not found
root@TAU-8:~# 13:04:58.676[app:dbg]VQ Conn 6 = MSP :        'create' =
-ash: 13:04:58.676[app:dbg]VQ: not found
root@TAU-8:~# 13:04:58.676[app:dbg]Creating connection 6....
-ash: 13:04:58.676[app:dbg]Creating: not found
root@TAU-8:~# 13:04:58.686[app:dbg]self_callstate_received (6934): complete
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.686[sip]nua: nua_application_event: entering
-ash: 13:04:58.686[sip]nua:: not found
root@TAU-8:~# 13:04:58.686[app:dbg]got nua_r_set_params : 200(OK)
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:58.686[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
-ash: 13:04:58.686[app:dbg]NO: not found
root@TAU-8:~# 13:04:58.676[app:dbg]Chan 6: INITIAL -> CREATING
-ash: cannot create CREATING: Read-only file system
-ash: 13:04:58.676[app:dbg]Chan: not found
root@TAU-8:~# 13:04:58.686[app:dbg]Created succefuly 6....
-ash: 13:04:58.686[app:dbg]Created: not found
root@TAU-8:~# 13:04:58.686[app:dbg]port 6: port_seize
-ash: 13:04:58.686[app:dbg]port: not found
root@TAU-8:~# 13:04:58.686[app:dbg]port 6: seize
-ash: 13:04:58.686[app:dbg]port: not found
root@TAU-8:~# 13:04:58.686[app:dbg]port 6: seize has cadence pulse = 0, pause = 0
-ash: 13:04:58.686[app:dbg]port: not found
root@TAU-8:~# 13:04:58.686[app:dbg]Set port 6 led to state 'LED_RINGING'
-ash: 13:04:58.686[app:dbg]Set: not found
root@TAU-8:~# 13:04:58.686[app:dbg]Port 6: user port 0, old state ringing, new state
-ash: 13:04:58.686[app:dbg]Port: not found
root@TAU-8:~# 13:04:58.686[app:dbg]Set port 6 led to state 'LED_OFF'
-ash: 13:04:58.686[app:dbg]Set: not found
root@TAU-8:~# 13:04:58.686[app:dbg]pbx -[msg_fxs_state]-> group
-ash: cannot create group: Read-only file system
-ash: 13:04:58.686[app:dbg]pbx: not found
root@TAU-8:~# 13:04:58.686[app:dbg]ITC: [msg_fxs_state] -> group
-ash: cannot create group: Read-only file system
-ash: 13:04:58.686[app:dbg]ITC:: not found
root@TAU-8:~# 13:04:58.686[app:dbg]-----[GM] self_fxs_state()
-ash: Syntax error: "(" unexpected
root@TAU-8:~# 13:04:58.686[app:dbg]Port 6: new state is ringing
-ash: 13:04:58.686[app:dbg]Port: not found
root@TAU-8:~# 13:04:58.686[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000004f
-ash: 13:04:58.686[app:dbg]vapi_cb_req:: not found
root@TAU-8:~# 13:04:58.706[app:dbg]pbx -[msg_free]-> sip
-ash: cannot create sip: Read-only file system
-ash: 13:04:58.706[app:dbg]pbx: not found
root@TAU-8:~# 13:04:58.706[app:dbg]SLIC 6: list of all calls:
-ash: 13:04:58.706[app:dbg]SLIC: not found
root@TAU-8:~# 13:04:58.706[app:dbg]   call ID: 02060005
-ash: 13:04:58.706[app:dbg]: not found
root@TAU-8:~# 13:04:58.706[app:dbg]incom_calls_add() add call 0x02060005, group -1, task <sip> to list
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.706[app:dbg]vapi_proc_event: VAPI_CB
-ash: 13:04:58.706[app:dbg]vapi_proc_event:: not found
root@TAU-8:~# 13:04:58.706[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000004f result 0x00000000
-ash: 13:04:58.706[app:dbg]vapi_cb_chan:: not found
root@TAU-8:~# 13:04:58.706[app:dbg]slic6. Event 6.
-ash: 13:04:58.706[app:dbg]slic6.: not found
root@TAU-8:~# 13:04:58.706[app:dbg]slic 6. Ring on event
-ash: 13:04:58.706[app:dbg]slic: not found
root@TAU-8:~# 13:04:58.706[app:dbg]Set port 6 led to state 'LED_RINGING'
-ash: 13:04:58.706[app:dbg]Set: not found
root@TAU-8:~# 13:04:58.706[app:dbg]ITC: [msg_free] -> sip
-ash: cannot create sip: Read-only file system
-ash: 13:04:58.706[app:dbg]ITC:: not found
root@TAU-8:~# 13:04:58.706[app:dbg]sip: call 02060005: endpoint 6 ringing
-ash: 13:04:58.706[app:dbg]sip:: not found
root@TAU-8:~# 13:04:58.706[app:dbg]sip: call 02060005,sip: INVITE: 180 Ringing
-ash: 13:04:58.706[app:dbg]sip:: not found
root@TAU-8:~# 13:04:58.706[app:dbg]send_18x() call 0x02060005, hdr <none>, sip, rel mode/cfg off/supp/req, inv w/ sdp, to port
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.706[app:dbg]send_18x(): respond w/o sdp 0, sdp 0
-ash: Syntax error: Bad function name
root@TAU-8:~# 13:04:58.706[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
-ash: 13:04:58.706[app:dbg]sdp_codecs_get_rfc2833:: not found
root@TAU-8:~# 13:04:58.706[app:dbg]Sending 180 Ringing without SDP
-ash: 13:04:58.706[app:dbg]Sending: not found
root@TAU-8:~# 13:04:58.706[sip]nua: nua_respond: entering
-ash: 13:04:58.706[sip]nua:: not found
root@TAU-8:~# 13:04:58.706[sip]nua(0x32bd00): sent signal r_respond
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.706[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000000
-ash: 13:04:58.706[app:dbg]vapi_cb_req:: not found
root@TAU-8:~# 13:04:58.706[sip]nua(0x32bd00): recv signal r_respond 180 Ringing
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.706[sip]nua: nua_stack_set_params: entering
-ash: 13:04:58.706[sip]nua:: not found
root@TAU-8:~# 13:04:58.706[sip]soa_set_params(static::0x32c100, ...) called
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.706[sip]nua: nua_invite_server_respond: entering
-ash: 13:04:58.706[sip]nua:: not found
root@TAU-8:~# 13:04:58.706[sip]tport_tsend(0x255000) tpn = UDP/91.215.252.131:5060
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.716[app:dbg]port_process (11051): seize next tone
-ash: Syntax error: word unexpected (expecting ")")
root@TAU-8:~# 13:04:58.716[app:dbg]port 6: clear
-ash: 13:04:58.716[app:dbg]port: not found
root@TAU-8:~# 13:04:58.716[app:dbg]Set port 6 led to state 'LED_OFF'
-ash: 13:04:58.716[app:dbg]Set: not found
root@TAU-8:~# 13:04:58.716[app:dbg]port 6: port_seize
-ash: 13:04:58.716[app:dbg]port: not found
root@TAU-8:~# 13:04:58.716[app:dbg]port 6: seize
-ash: 13:04:58.716[app:dbg]port: not found
root@TAU-8:~# 13:04:58.716[app:dbg]port 6: seize has cadence pulse = 1000, pause = 4000
-ash: 13:04:58.716[app:dbg]port: not found
root@TAU-8:~# 13:04:58.716[app:dbg]Set port 6 led to state 'LED_RINGING'
-ash: 13:04:58.716[app:dbg]Set: not found
root@TAU-8:~# 13:04:58.716[app:dbg]vapi_proc_event: VAPI_CB
-ash: 13:04:58.716[app:dbg]vapi_proc_event:: not found
root@TAU-8:~# 13:04:58.716[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000000 result 0x00000000
-ash: 13:04:58.716[app:dbg]vapi_cb_chan:: not found
root@TAU-8:~# 13:04:58.716[app:dbg]vapi: Conn 6 - << CREATED >>
-ash: Syntax error: newline unexpected
root@TAU-8:~# 13:04:58.716[app:dbg]vapi: Conn 6 - fix DTMF detector
> 13:04:58.716[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000049
13:04:58.716[sip]tport_by_addrinfo(0x255000): not found by name UDP/91.215.252.131:5060
13:04:58.716[sip]tport_vsend(0x255000): 499 bytes of 499 to udp/91.215.252.131:5060
13:04:58.716[sip]tport_vsend returned 499
13:04:58.716[sip]send 499 bytes to udp/[91.215.252.131]:5060 at 02:09:54.130000:
13:04:58.716[sip]   ------------------------------------------------------------------------
13:04:58.716[sip]   SIP/2.0 180 Ringing
13:04:58.716[sip]   Via: SIP/2.0/UDP 91.215.252.131:5060;rport=5060;branch=z9hG4bK858035671
13:04:58.716[sip]   From: <sip:3465265@10.10.10.245>;tag=1135724852
13:04:58.716[sip]   To: <sip:7001@10.10.10.37:5060>;tag=j52Hp2ym5QmZg
13:04:58.716[sip]   Call-ID: 1742192132@10.10.10.245
13:04:58.716[sip]   CSeq: 258 INVITE
13:04:58.716[sip]   Contact: <sip:7001@10.10.10.37:5060>
13:04:58.716[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33024470 sofia-sip/1.12.10
13:04:58.716[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
13:04:58.716[sip]   Supported: timer, 100rel, replaces
13:04:58.716[sip]   Content-Length: 0
13:04:58.716[sip]
13:04:58.716[sip]   ------------------------------------------------------------------------
13:04:58.716[sip]nta: sent 180 Ringing for INVITE (258)
13:04:58.716[sip]nua(0x32bd00): call state changed: received -> early
13:04:58.716[sip]nua(0x32bd00): event i_state 180 Ringing
13:04:58.716[sip]nua: nua_application_event: entering
13:04:58.716[app:dbg]got nua_i_state : 180(Ringing)
13:04:58.716[app:dbg]NO SIP IN nua_i_state == 180 : Ringing
13:04:58.716[app:dbg]self_i_state(): call state 6: : : sdp_recv no_oc
13:04:58.726[app:dbg]vapi_proc_event: VAPI_CB
13:04:58.726[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000049 result 0x00000000
13:04:58.726[app:dbg]vapi: Conn 6 - fix CNG generator
13:04:58.726[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000004c
13:04:58.736[app:dbg]vapi_proc_event: VAPI_CB
13:04:58.736[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000004c result 0x00000000
13:04:58.736[app:dbg]vapi: Conn 6 - caller id Set param
13:04:58.736[app:dbg]vapi: chan '6' set param Caller ID
13:04:58.736[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000000c
13:04:58.746[app:dbg]vapi_proc_event: VAPI_CB
13:04:58.746[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000000c result 0x00000000
13:04:58.746[app:dbg]vapi: Conn 6 - enable ind ptime and pt
13:04:58.746[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x0000004a
13:04:58.756[app:dbg]vapi_proc_event: VAPI_CB
13:04:58.756[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x0000004a result 0x00000000
13:04:58.756[app:dbg]Chan 6: CREATING -> CREATED
13:04:58.756[app:dbg]Port 6: check vapi queue ('busy''create') at vapi_next_ops:2532
13:04:58.866[sip]nta: timer set next to 59850 ms
13:04:59.756[app:dbg]slic6. Event 7.
13:04:59.756[app:dbg]slic 6. Ring off event
13:04:59.756[app:dbg]Set port 6 led to state 'LED_OFF'
13:04:59.756[app:dbg]Set port 6 led to state 'LED_OFF'
13:05:00.276[app:dbg]CMD_START_CID: port = 6
13:05:00.276[app:dbg]Port 6: check vapi queue ('free') at vapi_generate_offhook_caller_id:2885
13:05:00.276[app:dbg]Chan 6: current state is CREATED
13:05:00.276[app:dbg]Port 6: set vapi queue MSP to 'busy' with 'gen_offhook_caller_id' at vapi_generate_offhook_caller_id:2906
13:05:00.276[app:dbg]VQ Conn 6 = MSP : 'gen_offhook_caller_id' =
13:05:00.276[app:dbg]Caller ID date: 116.2.19 13:5:0
13:05:00.276[app:dbg]vapi: chan '6' generate Caller ID len=21
13:05:00.276[app:dbg]vapi_cb_req: 6 0 result 0x00000000 requid 0x00000a35
13:05:00.276[app:dbg]vapi_proc_event: VAPI_CB
13:05:00.276[app:dbg]vapi_cb_chan: chan 6 reqest_id 0x00000a35 result 0x00000000
13:05:00.276[app:dbg]chan 6: Offhook Caller ID generated
13:05:00.276[app:dbg]Port 6: check vapi queue ('busy''gen_offhook_caller_id') at vapi_next_ops:2532
13:05:00.846[app:dbg]slic6. Event 2.
13:05:00.846[app:dbg]slic 6. Off-hook event
13:05:00.846[app:dbg]Set port 6 led to state 'LED_ON'
13:05:00.846[app:dbg]HIO: offhook TDM port '6' port enabled 1
13:05:00.846[app:dbg]S
